What is the best way to log exceptions using ETW?

Question

Is there a standard way to log exceptions using ETW?

As far as I have seen the only way to do this is to log the message and possibly the inner exception message as there is not strongly typed parameter for the Exception type.

Answer 1

All CLR exceptions (first-chance, and the ones that may end up tearing down your application) are logged to ETW by the CLR Runtime provider, when enabled.

This is a fully "structured" event WITH callstacks (if you want them). In fact, you can write a monitoring application using the TraceEvent NuGet package (Install-Package Microsoft.Diagnostics.Tracing.TraceEvent)

I'm pasting monitoring code I often use. Put this in a console app, call the Run method, and throw some managed exceptions from any process, it'll print the information and their callstacks.

NOTE: You need the referenced NuGet package, and then reference its assemblies and then this code will compile.

class TraceLogMonitor
{
    static TextWriter Out = AllSamples.Out;

    public static void Run()
    {
        var monitoringTimeSec = 10;
       TraceEventSession session = null;

        Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs cancelArgs) =>
        {
            if (session != null)
                session.Dispose();
            cancelArgs.Cancel = true;
        };

        var exceptionGeneationTask = Task.Factory.StartNew(delegate
        {
            Thread.Sleep(3000);
            ThrowException();
        });

        Timer timer = null;

        using (session = new TraceEventSession("TraceLogSession"))
        {
            Out.WriteLine("Enabling Image load, Process and Thread events.  These are needed to look up native method names.");
            session.EnableKernelProvider(

                KernelTraceEventParser.Keywords.ImageLoad |
                KernelTraceEventParser.Keywords.Process,  
                KernelTraceEventParser.Keywords.None
                );

            Out.WriteLine("Enabling CLR Exception and Load events (and stack for those events)");

            session.EnableProvider(
                ClrTraceEventParser.ProviderGuid,
                TraceEventLevel.Informational,
                (ulong)(ClrTraceEventParser.Keywords.Jit |              
                ClrTraceEventParser.Keywords.JittedMethodILToNativeMap |
                ClrTraceEventParser.Keywords.Loader |                   
                ClrTraceEventParser.Keywords.Exception |               
                ClrTraceEventParser.Keywords.Stack));                   

            Out.WriteLine("Enabling CLR Events to 'catch up' on JIT compiled code in running processes.");
            session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Informational,
                (ulong)(ClrTraceEventParser.Keywords.Jit |          
                ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | 
                ClrTraceEventParser.Keywords.Loader |               
                ClrTraceEventParser.Keywords.StartEnumeration));    

            TextWriter SymbolLookupMessages = new StringWriter();

            var symbolPath = new SymbolPath(SymbolPath.SymbolPathFromEnvironment).Add(SymbolPath.MicrosoftSymbolServerPath);
            SymbolReader symbolReader = new SymbolReader(SymbolLookupMessages, symbolPath.ToString());

            Out.WriteLine("Open a real time TraceLog session (which understands how to decode stacks).");
            using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session)) 
            {
                Action<TraceEvent> PrintEvent = ((TraceEvent data) => Print(data, symbolReader));

                traceLogSource.Clr.ExceptionStart += PrintEvent;
                traceLogSource.Clr.LoaderModuleLoad += PrintEvent;

                traceLogSource.Kernel.PerfInfoSample += ((SampledProfileTraceData data) => Print(data, symbolReader));

                Out.WriteLine("Waiting {0} sec for Events.  Run managed code to see data. ", monitoringTimeSec);
                Out.WriteLine("Keep in mind there is a several second buffering delay");

                timer = new Timer(delegate(object state)
                {
                    Out.WriteLine("Stopped Monitoring after {0} sec", monitoringTimeSec);
                    if (session != null)
                        session.Dispose();
                    session = null;
                }, null, monitoringTimeSec * 1000, Timeout.Infinite);

                traceLogSource.Process();
            }
        }
        Out.WriteLine("Finished");
        if (timer != null)
            timer.Dispose();
    }

    static void Print(TraceEvent data, SymbolReader symbolReader)
    {
        if (data.Opcode == TraceEventOpcode.DataCollectionStart)
            return;

        if (data is ExceptionTraceData && ((ExceptionTraceData) data).ExceptionType.Length == 0)
            return;

        Out.WriteLine("EVENT: {0}", data.ToString());
        var callStack = data.CallStack();
        if (callStack != null)
        {
            ResolveNativeCode(callStack, symbolReader);
            Out.WriteLine("CALLSTACK: {0}", callStack.ToString());
        }
    }

    static private void ResolveNativeCode(TraceCallStack callStack, SymbolReader symbolReader)
    {
        while (callStack != null)
        {
            var codeAddress = callStack.CodeAddress;
            if (codeAddress.Method == null)
            {
                var moduleFile = codeAddress.ModuleFile;
                if (moduleFile == null)
                    Trace.WriteLine(string.Format("Could not find module for Address 0x{0:x}", codeAddress.Address));
                else
                    codeAddress.CodeAddresses.LookupSymbolsForModule(symbolReader, moduleFile);
            }
            callStack = callStack.Caller;
        }
    }

    [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)]
    private static void ThrowException()
    {
        ThrowException1();
    }

    [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)]
    private static void ThrowException1()
    {
        Out.WriteLine("Causing an exception to happen so a CLR Exception Start event will be generated.");
        try
        {
            throw new Exception("This is a test exception thrown to generate a CLR event");
        }
        catch (Exception) { }
    }
}

Answer 2

Use an extra Event and fire this event in the catch block and pass the exception message as a parameter to the Event

[Event(1, Message = "Application Falure: {0}", Level = EventLevel.Error, Keywords = Keywords.Diagnostic)]
public void Failure(string message) 
{ 
    if (this.IsEnabled())
    {
        this.WriteEvent(1, message); 
    }
}

Play with the Level and Keyword to control if you want to log it all the time or not.

Answer 3

ETW is not .NET specific, as such there isn't going to be any strongly typed .NET specifc API to log .net exceptions. You would instead create your own strongly typed API. This is the idea behind Semantic Logging and the Semantic Logging Application Block.