public void CreateOrOpenEventSessionTest()
{
string sessionName = "hiahiaSession";
Assert.IsNull(TraceEventSession.GetActiveSession(sessionName));
string logDir = TestUtility.TestDirectory + "\\hiahiaLogs";
if (!Directory.Exists(logDir))
{
Directory.CreateDirectory(logDir);
}
string logfile = logDir + "\\hiahia.etl";
TraceEventSession session = Utility.CreateOrOpenEventSession(sessionName, logfile);
session.EnableProvider(TraceEventProvider.Instance.Name);
// create again
session = Utility.CreateOrOpenEventSession(sessionName, logfile);
session.EnableProvider(TraceEventProvider.Instance.Name);
session.Dispose();
Assert.IsNull(TraceEventSession.GetActiveSession(sessionName));
Directory.Delete(logDir, recursive: true);
}
private void Window_Closed(object sender, EventArgs e)
{
// Cleanup TraceSession and temp update files...
TraceEventSession.GetActiveSession(SessionName)?.Stop(true);
_backgroundWorker.Dispose();
if (_updateStarted)
{
return;
}
try
{
if (_updateTempFileName == null)
{
return;
}
if (!File.Exists(_updateTempFileName))
{
File.Delete(_updateTempFileName);
}
}
catch (Exception)
{
// ignored
}
}
private static string WriteTestFile(string logFilename)
{
LogManager.Start();
LogManager.SetConfiguration(null);
LogManager.AllowEtwLogging = AllowEtwLoggingValues.Enabled;
string fullFilename = Path.Combine(LogManager.DefaultDirectory, logFilename);
try
{
File.Delete(fullFilename);
}
catch (DirectoryNotFoundException) { }
string sessionName = Path.GetFileNameWithoutExtension(logFilename);
IEventLogger logger = LogManager.CreateETWLogger(sessionName, ".");
logger.SubscribeToEvents(TestLogger.Write.Guid, EventLevel.Verbose);
while (TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + sessionName) == null)
{
// Ensure session starts...
Thread.Sleep(100);
}
// Even after the session is listed it seemingly isn't "ready", periodic test failures seem to occur without
// an enforced pause here.
Thread.Sleep(100);
WriteTestEvents();
LogManager.DestroyLogger(logger);
LogManager.Shutdown();
Assert.IsTrue(File.Exists(fullFilename));
return(fullFilename);
}
/// <summary>
/// Creates a Task with no return value that hosts the event processing loop. Ensures the session is started
/// prior to returning.
/// </summary>
/// <returns>A Task to handle the event processing.</returns>
public Task CreateProcessingTask()
{
var task = new Task(this.Process);
task.Start();
int waitTime = 5000;
while (waitTime > 0 && TraceEventSession.GetActiveSession(this.sessionName) == null)
{
if (task.IsFaulted)
{
throw new OperationCanceledException("Unable to start realtime session.", task.Exception);
}
Thread.Sleep(100);
waitTime -= 100;
}
if (TraceEventSession.GetActiveSession(this.sessionName) == null)
{
throw new OperationCanceledException("Unable to start realtime session.");
}
return(task);
}
private string CleanupMatchingSessions(string sessionNamePrefix, bool keepOne)
{
string result = null;
foreach (var sesName in TraceEventSession.GetActiveSessionNames())
{
if (!sesName.StartsWith(sessionNamePrefix, StringComparison.OrdinalIgnoreCase))
{
continue;
}
var session = TraceEventSession.GetActiveSession(sesName);
if (session == null || !session.IsRealTime)
{
continue;
}
if (keepOne && result == null)
{
result = session.SessionName;
}
else
{
session.Dispose();
}
}
return(result);
}
public void Start(int pid)
{
TraceEventSession.GetActiveSession("HeapSession")?.Dispose();
_session = new TraceEventSession("HeapSession");
_session.EnableWindowsHeapProvider(pid);
_session.Source.Dynamic.All += Source_AllEvents;
_session.Source.Kernel.StackWalkStack += Kernel_StackWalkStack;
Task.Factory.StartNew(() => _session.Source.Process());
}
public static void ClearAllActiveObservableEventListenerSession()
{
var activeSessions = TraceEventSession.GetActiveSessionNames()
.Where(x => x.StartsWith("ObservableEventListener"))
.Select(x => TraceEventSession.GetActiveSession(x));
var activeCount = 0;
foreach (var item in activeSessions)
{
item.Dispose();
activeCount++;
}
Console.WriteLine("Cleared ActiveSession's Count:" + activeCount);
}
public void Cleanup()
{
try
{
// This clean up is there to clean up possible left over trace event sessions during the Debug of the unit tests.
foreach (var name in TraceEventSession.GetActiveSessionNames().Where(n => n.StartsWith("ApplicationInsights-", StringComparison.Ordinal)))
{
TraceEventSession.GetActiveSession(name).Stop();
}
}
catch
{
// This should normally not happen. But if this happens, there's, unfortunately, nothing too much we can do here.
}
}
public WMIEventParser(TraceLogEventSource source, string autoLoggerSessionName, string autoLoggerFileName)
{
mySource = source;
source.Kernel.ProcessStart += Kernel_ProcessStart;
source.Kernel.ProcessStop += Kernel_ProcessStop;
// stop already started autologger sessoin which runs since boot
// this way we capture all WMI events even the ones which did happen while our service was already starting!
// It can happen that we duplicate some events but that is still better than to loose important polling events
// which can happen in services which run early in the boot phase.
var fileSession = TraceEventSession.GetActiveSession(autoLoggerSessionName);
fileSession?.Stop();
// Only parse when session was still running otherwise we would inject old events upon session restart again
if (fileSession != null)
{
using WMIETlFileReader reader = new WMIETlFileReader(Environment.ExpandEnvironmentVariables(autoLoggerFileName));
myUnprocessedEvents = reader.GetPreviousStartEvents();
}
}
public override void Process()
{
if (TraceEventSession.GetActiveSession(this.sessionName) != null)
{
if (!this.reclaimSession)
{
throw new OperationCanceledException("Session already exists with name " + this.sessionName);
}
ETLFileLogger.CloseDuplicateTraceSession(this.sessionName);
}
this.CurrentSessionName = this.sessionName;
this.session = new TraceEventSession(this.sessionName, null);
foreach (var subscription in this.enabledProviders)
{
Guid providerID = subscription.Item1;
var minimumSeverity = (TraceEventLevel)subscription.Item2;
ulong keywords = subscription.Item3;
if (providerID == ClrTraceEventParser.ProviderGuid)
{
this.ProcessEventTypes |= EventTypes.Clr;
}
else if (providerID == KernelTraceEventParser.ProviderGuid)
{
this.ProcessEventTypes |= EventTypes.Kernel;
}
else
{
this.ProcessEventTypes |= EventTypes.EventSource;
}
this.session.EnableProvider(providerID, minimumSeverity, keywords);
}
// Ordering seems to matter here! If we create the source before there's something happening in the
// session we end up with invalid timestamps and no events get emitted. Keep this here.
this.TraceEventSource = new ETWTraceEventSource(this.sessionName, TraceEventSourceType.Session);
this.ProcessEvents();
}
private string WriteTestFile(string logFilename)
{
LogManager.Start();
LogManager.SetConfiguration((Configuration)null);
LogManager.Configuration.AllowEtwLogging = Configuration.AllowEtwLoggingValues.Enabled;
string fullFilename = Path.Combine(LogManager.DefaultDirectory, logFilename);
try
{
File.Delete(fullFilename);
}
catch (DirectoryNotFoundException) { }
var sName = Path.GetFileNameWithoutExtension(logFilename);
var subs = new[] { new EventProviderSubscription(TestLogger.Write.Guid, EventLevel.Verbose) };
var config = new LogConfiguration(sName, LogType.EventTracing, subs)
{
Directory = "."
};
IEventLogger logger = LogManager.CreateLogger <ETLFileLogger>(config);
logger.SubscribeToEvents(TestLogger.Write.Guid, EventLevel.Verbose);
this.sessionName = ETLFileLogger.SessionPrefix + sName;
while (TraceEventSession.GetActiveSession(this.sessionName) == null)
{
// Ensure session starts...
Thread.Sleep(100);
}
// Even after the session is listed it seemingly isn't "ready", periodic test failures seem to occur without
// an enforced pause here. This is awful and the author feels very bad about it. Sorry?
Thread.Sleep(100);
WriteTestEvents();
LogManager.DestroyLogger(logger);
LogManager.Shutdown();
Assert.IsTrue(File.Exists(fullFilename));
return(fullFilename);
}
private static void WorkerTraceEvents(object sender, DoWorkEventArgs e)
{
try
{
if (TraceEventSession.IsElevated() != true)
{
throw new InvalidOperationException(
"Collecting ETW trace events requires administrative privileges.");
}
if (TraceEventSession.GetActiveSessionNames().Contains(SessionName))
{
Debug.WriteLine(
$"The session name '{SessionName}' is already in use, stopping existing and restart a new one.");
TraceEventSession.GetActiveSession(SessionName).Stop(true);
}
// An End-To-End ETW Tracing Example: EventSource and TraceEvent
// https://blogs.msdn.microsoft.com/vancem/2012/12/20/an-end-to-end-etw-tracing-example-eventsource-and-traceevent/
using (var traceEventSession = new TraceEventSession(SessionName))
{
traceEventSession.StopOnDispose = true;
using (var traceEventSource = new ETWTraceEventSource(SessionName, TraceEventSourceType.Session))
{
traceEventSession.EnableProvider(OmaDmClient);
traceEventSession.EnableProvider(OmaDmClientProvider);
new RegisteredTraceEventParser(traceEventSource).All += (data =>
(sender as BackgroundWorker)?.ReportProgress(0, data.Clone()));
traceEventSource.Process();
}
}
}
catch (Exception ex)
{
Debug.WriteLine($"Exception: {ex}");
}
}
public void TestSessionClosing()
{
LogManager.Shutdown(); // not needed by us
// set this just to make sure it isn't actually used.
LogManager.AllowEtwLogging = AllowEtwLoggingValues.Disabled;
File.Delete("fakesession.etl");
var s1 = new TraceEventSession(ETLFileLogger.SessionPrefix + "fakeSession", "fakeSession.etl");
s1.EnableProvider(TestLogger.Write.Guid, TraceEventLevel.Verbose);
s1.StopOnDispose = false;
TestLogger.Write.String("mc frontalot = nerdcore raps");
Assert.IsTrue(File.Exists("fakesession.etl"));
Assert.IsNotNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
s1.Dispose();
// so the session should still exist ...
Assert.IsNotNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
var s2 = new ETLFileLogger("fakeSession", "fakeSession.etl", 64);
s2.SubscribeToEvents(TestLogger.Write.Guid, EventLevel.Verbose);
TestLogger.Write.String("optimus rhyme = also rapping nerd");
s2.Dispose();
const int maxWait = 1000;
int slept = 0;
while (slept < maxWait)
{
if (TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession") == null)
{
break;
}
Thread.Sleep(maxWait / 10);
slept += maxWait / 10;
}
Assert.IsNull(TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + "fakeSession"));
}
protected override void OnStop()
{
// Guardrail for timeout
RequestAdditionalTime(5000);
// Check if any collector tasks are registered
if (SilkUtility.CollectorTaskList.Any())
{
// We pop terminated threads out of the list
foreach (CollectorInstance CollectorTask in SilkUtility.CollectorTaskList)
{
try
{
CollectorTask.EventSource.StopProcessing();
TraceEventSession.GetActiveSession(CollectorTask.EventParseSessionName).Dispose();
SilkUtility.CollectorTaskList.Remove(CollectorTask);
SilkUtility.WriteCollectorGuidMessageToServiceTextLog(CollectorTask.CollectorGUID, "Collector terminated", false);
} catch { }
}
}
// Write status to log
SilkUtility.WriteToServiceTextLog("[+] SilkService stopped at: " + DateTime.Now);
}
public void ChangingETLFilenameCausesManifestToBeEmittedInNewFile()
{
const string prefix = "rotateFile";
var files = new[] { prefix + "1.etl", prefix + "2.etl", prefix + "3.etl" };
var resultFiles = new List <string>();
LogManager.Start();
LogManager.SetConfiguration(null);
LogManager.AllowEtwLogging = AllowEtwLoggingValues.Enabled;
string sessionName = null;
ETLFileLogger logger = null;
foreach (var logFilename in files)
{
string fullFilename = Path.Combine(LogManager.DefaultDirectory, logFilename);
try
{
File.Delete(fullFilename);
}
catch (DirectoryNotFoundException) { }
if (sessionName == null)
{
sessionName = Path.GetFileNameWithoutExtension(logFilename);
}
if (logger == null)
{
logger = LogManager.CreateETWLogger(sessionName, ".") as ETLFileLogger;
logger.SubscribeToEvents(TestLogger.Write.Guid, EventLevel.Verbose);
while (TraceEventSession.GetActiveSession(ETLFileLogger.SessionPrefix + sessionName) == null)
{
// Ensure session starts...
Thread.Sleep(100);
}
// Even after the session is listed it seemingly isn't "ready", periodic test failures seem to occur without
// an enforced pause here.
Thread.Sleep(100);
}
else
{
logger.Filename = fullFilename;
}
WriteTestEvents();
Assert.IsTrue(File.Exists(fullFilename));
resultFiles.Add(fullFilename);
}
LogManager.DestroyLogger(logger);
LogManager.Shutdown();
foreach (var fullFilename in resultFiles)
{
// It is critical to ensure we create a new reader for each file so that any history across files is
// not preserved
using (var reader = new ETWFileProcessor(fullFilename))
{
reader.EventProcessed += ValidateEventArgs;
reader.Process();
Assert.AreEqual(4, reader.Count);
}
}
}
public void CollectGcMetrics()
{
var logger = new TestLogger(LogLevel.Trace);
string traceEventSessionName;
using (var gcMetricsProvider = new GcMetricsProvider(logger))
{
traceEventSessionName = gcMetricsProvider.TraceEventSessionName;
gcMetricsProvider.IsMetricAlreadyCaptured.Should().BeFalse();
#if !NETCOREAPP2_1
//EventSource Microsoft-Windows-DotNETRuntime is only 2.2+, no gc metrics on 2.1
//repeat the allocation multiple times and make sure at least 1 GetSamples() call returns value
// ReSharper disable once TooWideLocalVariableScope
// ReSharper disable once RedundantAssignment
var containsValue = false;
for (var j = 0; j < 1000; j++)
{
for (var i = 0; i < 300_000; i++)
{
var _ = new int[100];
}
GC.Collect();
for (var i = 0; i < 300_000; i++)
{
var _ = new int[100];
}
GC.Collect();
var samples = gcMetricsProvider.GetSamples();
containsValue = samples != null && samples.Any();
if (containsValue)
{
break;
}
}
if (PlatformDetection.IsDotNetFullFramework)
{
if (logger.Lines.Any(n => n.Contains("TraceEventSession initialization failed - GC metrics won't be collected")))
{
// If initialization fails, (e.g. because ETW session initalization fails) we don't assert
_output.WriteLine("Initialization failed. don't make assertions");
return;
}
}
if (PlatformDetection.IsDotNetCore || PlatformDetection.IsDotNet5)
{
if (!logger.Lines.Any(n => n.Contains("OnEventWritten with GC")))
{
// If no OnWritten with a GC event was called then initialization failed -> we don't assert
_output.WriteLine("Initialization failed. don't make assertions");
return;
}
}
containsValue.Should().BeTrue();
gcMetricsProvider.IsMetricAlreadyCaptured.Should().BeTrue();
#endif
}
if (PlatformDetection.IsDotNetFullFramework)
{
var traceEventSession = TraceEventSession.GetActiveSession(traceEventSessionName);
traceEventSession.Should().BeNull();
}
}
public void CollectGcMetrics()
{
var logger = new TestLogger(LogLevel.Trace);
string traceEventSessionName;
using (var gcMetricsProvider = new GcMetricsProvider(logger))
{
traceEventSessionName = gcMetricsProvider.TraceEventSessionName;
gcMetricsProvider.IsMetricAlreadyCaptured.Should().BeFalse();
#if !NETCOREAPP2_1
//EventSource Microsoft-Windows-DotNETRuntime is only 2.2+, no gc metrics on 2.1
//repeat the allocation multiple times and make sure at least 1 GetSamples() call returns value
// ReSharper disable once TooWideLocalVariableScope
// ReSharper disable once RedundantAssignment
var containsValue = false;
var hasGenSize = false;
var hasGcTime = false;
for (var j = 0; j < 10; j++)
{
for (var i = 0; i < 500; i++)
{
var array = new int[10000000];
// In order to make sure the line above is not optimized away, let's use the array:
Console.WriteLine($"GC test, int[] allocated with length: {array.Length}");
}
GC.Collect(2, GCCollectionMode.Forced, true, true);
GC.WaitForFullGCComplete();
GC.Collect(2, GCCollectionMode.Forced, true, true);
for (var i = 0; i < 500; i++)
{
var array = new int[10000000];
// In order to make sure the line above is not optimized away, let's use the array:
Console.WriteLine($"GC test, int[] allocated with length: {array.Length}");
}
GC.Collect(2, GCCollectionMode.Forced, true, true);
GC.WaitForFullGCComplete();
GC.Collect(2, GCCollectionMode.Forced, true, true);
var samples = gcMetricsProvider.GetSamples()?.ToArray();
containsValue = samples != null && samples.Any();
hasGenSize = samples != null && samples
.Any(n => (n.KeyValue.Key.Contains("gen0size") || n.KeyValue.Key.Contains("gen1size") ||
n.KeyValue.Key.Contains("gen2size") || n.KeyValue.Key.Contains("gen3size")) &&
n.KeyValue.Value > 0);
hasGcTime = samples != null && samples
.Any(n => n.KeyValue.Key.Contains("clr.gc.time") && n.KeyValue.Value > 0);
if (containsValue && hasGenSize && hasGcTime)
{
break;
}
}
if (PlatformDetection.IsDotNetFullFramework)
{
if (logger.Lines.Any(n => n.Contains("TraceEventSession initialization failed - GC metrics won't be collected")))
{
// If initialization fails, (e.g. because ETW session initalization fails) we don't assert
_output.WriteLine("Initialization failed. don't make assertions");
return;
}
}
if (PlatformDetection.IsDotNetCore || PlatformDetection.IsDotNet5)
{
if (!logger.Lines.Any(n => n.Contains("OnEventWritten with GC")))
{
// If no OnWritten with a GC event was called then initialization failed -> we don't assert
_output.WriteLine("Initialization failed. don't make assertions");
return;
}
}
containsValue.Should().BeTrue();
hasGenSize.Should().BeTrue();
hasGcTime.Should().BeTrue();
gcMetricsProvider.IsMetricAlreadyCaptured.Should().BeTrue();
#endif
}
if (PlatformDetection.IsDotNetFullFramework)
{
var traceEventSession = TraceEventSession.GetActiveSession(traceEventSessionName);
traceEventSession.Should().BeNull();
}
}