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.

Christlike

Answer 1

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.

Hypnotherapy

Because you can't use strongly type exceptions against the EventSource would I be best just calling it like so: EventSource.Log.Failure(MyException.ToString())? – Christlike

Answer 2

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) { }
    }
}

Mameluke

I'm seeing the following exception when calling CallStack(): Attempted to use TraceLog support on a non-TraceLog TraceEventSource Ever seen this before? – Cerous

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.

Anthelion

so at the end of the day in order to use ETW only primitive data types can be used, strings and numbers (in the form of strings)? Is purely serializing the Exception into a string good enough? Or is there some pattern for non-.net applications to trace exceptions? – Louise

ETW is a binary payload, and supports structs of your definition. msdn.microsoft.com/en-us/library/windows/desktop/… It's just that when you do go this route you have to write a custom decoder. In the .NET case, there is a well-defined one already provided by the .NET Team. However, like many things in native code, there is more than one way to do it. C++ Exceptions? SEH exceptions? etc. The most interest part of an exception is the callstack (and its EIPs, to get line numbers), which is standardized by ETW, and its stack walker. Any info beyond that is your call. – Mameluke