alexfelton / etwstreamcore

Logs are event streams. EtwStream provides In-Process and Out-of-Process ObservableEventListener. Everything can compose and output to anywhere by Reactive Extensions.

EtwStream

ETW(Event Tracing for Windows) and EventSource is important feature for structured logging in .NET. But monitoring log stream is very hard. EtwStream provides LINQPad integartion, you can dump ETW stream simply like log viewer.

EtwStream is full featured logger, In-Process Rx Logger and Out-of-Process next generation logging service with C# Scripting config. You can replace log4net/NLog/Serilog/SLAB etc. Please see EtwStream.Core and EtwStream.Service section.

LINQPad Viewer

PM> Install-Package EtwStream.LinqPad

ObservableEventListener + WithColor for Expression/DumpWithColor for Statement mode, dump event stream with colored and auto scrolling(stop auto scroll, use Ctrl+Shift+E shortcut).

LINQPad's default rows limit is 1000 line. You can expand to 10000 rows at Preferences -> Results -> Maximum rows to display.

EtwStream.LinqPad only supports LINQPad 5. LINQPad 4 isn't supported.

ObservableEventListener

ObservableEventListener provides five ways for observe log events.

Method	Description
FromEventSource	Observe In-Process EventSource events. It's no across ETW.
FromTraceEvent	Observe Out-of-Process ETW Realtime session.
FromClrTraceEvent	Observe Out-of-Process ETW CLR TraceEvent.
FromKernelTraceEvent	Observe Out-of-Process ETW Kernel TraceEvent.
FromFileTail	Observe String-Line from file like tail -f.

You usually use FromTraceEvent, it can observe own defined EventSource and built-in EventSource such as TplEventSource. withProcessName: true, dump with process name.

FromFileTail is not ETW/EventSouce but useful method. It's like tail -f. FromFileTail does not enable auto scrolling automatically. You should enable AutoScrollResults = true manually.

Util.AutoScrollResults = true;

ObservableEventListener.FromFileTail(@"C:\log.txt")
.Dump();

with Reactive Extensions

Everything is IObservable! You can filter, merge, grouping log events by Reactive Extensions.

Observable.Merge(
    ObservableEventListener.FromTraceEvent("LoggerEventSource"),
    ObservableEventListener.FromTraceEvent("MyCompanyEvent"),
    ObservableEventListener.FromTraceEvent("PhotonWire")
)
.DumpWithColor(withProviderName: true);

withProviderName: true, shows provider name so you can distinguish merged event source.

EtwStream.Core/EtwStream.InProcess

EtwStream's Core Engine can use all .NET apps. EtwStream is both for In-Process and Out-of-Process. EtwStream.InProcess is subset of EtwStream, only for In-Process logging so it no dependent Microsoft.Diagnostics.Tracing.TraceEvent.

PM> Install-Package EtwStream
PM> Install-Package EtwStream.InProcess

ObservableEventListener is simple wrapper of EventListener and TraceEvent(Microsoft.Diagnostics.Tracing.TraceEvent). You can control there easily.

LogToXxx methods are sink(output plugin). Here is the currently available lists.

Sink Method	Description
LogToConsole	Output by Console.WriteLine with colored.
LogToDebug	Output by Debug.WriteLine.
LogToTrace	Output by Trace.WriteLine.
LogToFile	Output to flat file.
LogToRollingFile	Output to flat file with file rotate.
LogTo	LogTo is helper for multiple subscribe.

How to make original Sink? I recommend log to Azure EventHubs, AWS Kinesis, BigQuery Streaming insert directly. Log to file is legacy way! Document is not available yet. Please see Sinks codes and please here to me.

EtwStream's FileSink is fastest file logger, I'll show benchmark results.

You can control asynchronous/buffered events(should control there manualy).

static void Main()
{
    // in ApplicationStart, prepare two parts.
    var cts = new CancellationTokenSource();
    var container = new SubscriptionContainer();
    
    // configure log
    ObservableEventListener.FromTraceEvent("SampleEventSource")
        .Buffer(TimeSpan.FromSeconds(5), 1000, cts.Token)
        .LogToFile("log.txt", x => $"[{DateTime.Now.ToString("yyyy/MM/dd hh:mm:ss")}][{x.Level}]{x.DumpPayload()}", Encoding.UTF8, autoFlush: true)
        .AddTo(container);
        
    // Application Running....
        
    // End of Application(Form_Closed/Application_End/Main's last line/etc...)
    cts.Cancel();        // Cancel publish rest of buffered events.
    container.Dispose(); // Wait finish of subscriptions's buffer event.
}

Buffer(TimeSpan, int, CancellationToken) and TakeUntil(CancellationToken) is special helper methods of EtwStream. Please use before Subscribe(LogTo) operator. After Subscribe(LogTo), you can use AddTo helper method to SubscriptionContainer. It enables wait subscription complete with CancellationToken.

LogTo and LogToRollingFile example

ObservableEventListener.FromTraceEvent("SampleEventSource")
    .Buffer(TimeSpan.FromSeconds(5), 1000, cts.Token)
    .LogTo(xs =>
    {
        // LogTo defines multiple output.

        // RollingFile:
        // fileNameSelector's DateTime is date of file open time, int is number sequence.
        // timestampPattern's DateTime is write time of message. If pattern is different then roll new file.
        // timestampPattern must be integer at last word.
        var d1 = xs.LogToRollingFile(
            fileNameSelector: (dt, i) => $@"{dt.ToString("yyyyMMdd")}_MyLog_{i.ToString("00")}.log",
            timestampPattern: x => x.ToString("yyyyMMdd"),
            rollSizeKB: 10000,
            messageFormatter: x => x.DumpPayloadOrMessage(),
            encoding: Encoding.UTF8,
            autoFlush: false);

        var d2 = xs.LogToConsole();
        var d3 = xs.LogToDebug();

        return new[] { d1, d2, d3 }; // return all subscriptions
    })
    .AddTo(container);

EventWrittenEventArgs and TraceEvent are extended some methos for format message.

Method	Description
DumpPayload	Convert payloads to human readable message.
DumpPayloadOrMessage	If message is exists, return formatted message. Otherwise convert payloads to human readable message.
DumpFormattedMessage	(EventWrittenEventArgs only), return formatted message.
ToJson	Return json formatted payloads.

EtwStream.Service

EtwStream.Service is Out-Of-Process worker of EtwStream. It's built on Topshelf. You can execute direct(for Console Application Viewer) or install Windows Service(EtwStreamService.exe -install).

You can download binary from releases page, EtwStream.Service_*.*.*.zip -> EtwStraem/releases. execute as Logging Viewer. -install as Windows Service.

The concept is same as Semantic Logging Application Block's Out-of-Process Service. Different is configure by Roslyn C# Scripting and supports Self-describing events of .NET 4.6 EventSource.

Configuration is csx. You can write full Rx and C# codes. for example

// configuration.csx

// Buffering 5 seconds or 1000 count
// Output format is Func<TraceEvent, string>
ObservableEventListener.FromTraceEvent("SampleEventSource")
    .Buffer(TimeSpan.FromSeconds(5), 1000, EtwStreamService.TerminateToken)
    .LogToFile("log.txt", x => $"[{DateTime.Now.ToString("yyyy/MM/dd hh:mm:ss")}][{x.Level}]{x.DumpPayload()}", Encoding.UTF8, autoFlush: true)
    .AddTo(EtwStreamService.Container);

Everything is C#, you can compose, routing by Rx. It is no different with In-Process and Out-of-Process. Off course you can use System.Configuration.ConfigurationManager.AppSettings, WebClient, from file, etc everything.

LINQPad helps write csx

Current csx editor is very poor. LINQPad can save your blues.

EtwStream.LINQPad has EtwStream.Service's shim. You can compile and run by LINQPad, and paste to csx, it's works.

LoggerEventSource

First step for use EventSource. Here is simply legacy-unstructured-logging style logger.

[EventSource(Name = "LoggerEventSource")]
public class LoggerEventSource : EventSource
{
    public static readonly LoggerEventSource Log = new LoggerEventSource();

    public class Keywords
    {
        public const EventKeywords Logging = (EventKeywords)1;
    }

    string FormatPath(string filePath)
    {
        if (filePath == null) return "";

        var xs = filePath.Split('\\');
        var len = xs.Length;
        if (len >= 3)
        {
            return xs[len - 3] + "/" + xs[len - 2] + "/" + xs[len - 1];
        }
        else if (len == 2)
        {
            return xs[len - 2] + "/" + xs[len - 1];
        }
        else if (len == 1)
        {
            return xs[len - 1];
        }
        else
        {
            return "";
        }
    }

    [Event(1, Level = EventLevel.LogAlways, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void LogAlways(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(1, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(2, Level = EventLevel.Critical, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Critical(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(2, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(3, Level = EventLevel.Error, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Error(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(3, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(4, Level = EventLevel.Warning, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Warning(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(4, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(5, Level = EventLevel.Informational, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Informational(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(5, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(6, Level = EventLevel.Verbose, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Verbose(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(6, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(7, Level = EventLevel.Error, Keywords = Keywords.Logging, Version = 1)]
    public void Exception(string type, string stackTrace, string message)
    {
        WriteEvent(7, type ?? "", stackTrace ?? "", message ?? "");
    }

    [Conditional("DEBUG")]
    [Event(8, Level = EventLevel.Verbose, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Debug(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(8, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [NonEvent]
    public IDisposable MeasureExecution(string label, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        return new StopwatchMonitor(this, label ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(9, Level = EventLevel.Informational, Keywords = Keywords.Logging, Message = "[{0}][{2}:{3}][{1}]{4}ms")]
    void MeasureExecution(string label, string memberName, string filePath, int line, double duration)
    {
        WriteEvent(9, label ?? "", memberName ?? "", FormatPath(filePath) ?? "", line, duration);
    }

    class StopwatchMonitor : IDisposable
    {
        readonly LoggerEventSource logger;
        readonly string label;
        readonly string memberName;
        readonly string filePath;
        readonly int line;
        Stopwatch stopwatch;

        public StopwatchMonitor(LoggerEventSource logger, string label, string memberName, string filePath, int line)
        {
            this.logger = logger;
            this.label = label;
            this.memberName = memberName;
            this.filePath = filePath;
            this.line = line;
            stopwatch = Stopwatch.StartNew();
        }

        public void Dispose()
        {
            if (stopwatch != null)
            {
                stopwatch.Stop();
                logger.MeasureExecution(label, memberName, filePath, line, stopwatch.Elapsed.TotalMilliseconds);
                stopwatch = null;
            }
        }
    }
}

This is basic definition. Next step, you should define own method for structured-logging.

Wellknown EventSources

Following Guid is providing by EtwStream.WellKnownEventSources.

• System.Diagnostics.Eventing.FrameworkEventSource - 8E9F5090-2D75-4d03-8A81-E5AFBF85DAF1
• System.Collections.Concurrent.ConcurrentCollectionsEventSource - 35167F8E-49B2-4b96-AB86-435B59336B5E
• System.Threading.SynchronizationEventSource - EC631D38-466B-4290-9306-834971BA0217
• System.Threading.Tasks.TplEventSource - 2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5
• PinnableBufferCacheEventSource - Microsoft-DotNETRuntime-PinnableBufferCache-System
• System.Linq.Parallel.PlinqEventSource - 159eeeec-4a14-4418-a8fe-faabcd987887
• SqlEventSource - Microsoft-AdoNet-SystemData
• Microsoft-Windows-ASPNET - ee799f41-cfa5-550b-bf2c-344747c1c668

IIS 8.5 Logging to ETW

Following Guid is providing by EtwStream.IISEventSources.

• Microsoft-Windows-HttpEvent - 7B6BC78C-898B-4170-BBF8-1A469EA43FC5
• Microsoft-Windows-HttpLog - C42A2738-2333-40A5-A32F-6ACC36449DCC
• Microsoft-Windows-HttpService - DD5EF90A-6398-47A4-AD34-4DCECDEF795F
• Microsoft-Windows-Runtime-Web-Http - 41877CB4-11FC-4188-B590-712C143C881D
• Microsoft-Windows-Runtime-WebAPI - 6BD96334-DC49-441A-B9C4-41425BA628D8
• ASP.NET Events - AFF081FE-0247-4275-9C4E-021F3DC1DA35
• Microsoft-Windows-IIS-APPHOSTSVC - CAC10856-9223-48FE-96BA-2A772274FB53
• Microsoft-Windows-IIS-Logging - 7E8AD27F-B271-4EA2-A783-A47BDE29143B
• Microsoft-Windows-IIS-W3SVC - 05448E22-93DE-4A7A-BBA5-92E27486A8BE