Why doesn't my EventSource produce any events?

  • [アーティクル]

This is a quick entry to warn about a pitfall that you are likely to run into sooner or later if you build or maintain EventSources.  

As I have blogged about, it is very easy to get started with EventSources.   Here is some code that someone might write

 

 And then use it by using by doing

  • MyEventSource.Log.MyFirstMessage("The time is " + DateTime.Now);

 You turn your EventSource on by doing

  • PerfView /providers=*MyEventSource run MyApp.exe

but you find that there are no events in the resulting log file from MyEventSource!    

What is going on?   The root of the problem is that there is a bug in the code above (can you spot it?).   Notice that the First and second message call 'WriteEvent' with exactly the same ID.  This is a mistake.   Each event in an eventSource must be given a unique ID.  In fact the rule is stricter than that:  the event you pass 'WriteEvent' must be exactly the event ID that EventSource thinks it should have.   This ID is either

  1. The ID assigned to it explicitly with the Event attribute (not used in the above case) OR
  2. The ordinal number of logging methods' where a logging method is defined to be a method that returns void.  

Thus 'MySecondMessage MUST use the ID 2, not 1 (since it is the second logging message in the class).   This insures that there is a unique ID given to each event that an EventSource generates.  EventSource checks for this and throws an exception if this (and many other error conditions) occur.  

So where is my Exception?  This is the unfortunate part.   Late in the development of EventSource users made the strong request that EventSource NEVER FAIL by default.   This is a useful property, as logging is often 'optional' and you don't want to some startup error with ETW to cause your application to fail.   This feature was implemented by simply wrapping the body of the constructor in a try-catch, which sets a flag in the catch clause that will make any subsequent WriteEvent call simply do nothing.  

This satisfies the desire for EventSource to never throw, but it also makes finding any mistake in your EventSource very difficult.    Worse, there seems to be a bug in VS where exception that are caught are not always displayed in the output window and setting the 'Exceptions' dialog to stop on any exception thrown does not seem to work (probably because in the typical case EventSource is called from the class constructor (to initialize a static variable)). 

This is all very unfortunate, and leads to 'mysterious' failures if you make ANY mistake in your EventSource. 

The good news is that there is a pretty easy work-around that works today.   It is simply this

  • When you make any changes to your EventSource, immediately use PerfView /providers=*EventSourceName collect  test it.  (That is use PerfView's default settings and your provider to turn it on)
  • If you don't find your events as expected, Open the 'Exceptions Stacks' view in the data file

This will show you something like this

Which shows you all exceptions thrown during the trace, include any that were swallowed by a try-catch in the implementation of EventSource. 

Notice that you get the exactly exception message, which tells you pretty clearly what you did wrong (in the example above the 'EventMessage1' event was passed 1 but it should have been 2.

So the simple advice is

  • if your EventSource is not working after an update, simply look at the 'Exceptions view'. 

What is nice is that once you know about this, it is probably EASIER than trying to debug it in the debugger (because you had to use something to turn on the provider anyway).   Now you don't even need a debugger to resolve the issue.

Comments

  • Anonymous
    December 21, 2012
    Just a question about WPR and managed call stacks. Your tool seems to be able to do stackwalking with .NET 4.0 correctly. WPR can do it as well but it seems that it does stop at the first managed frame it can find. Is this intentional or is there a workaround? I have posted the issue at the forum (social.msdn.microsoft.com/.../b7098a78-6600-456a-813e-79a84b994f32) but unfortunately nobody seems to care.

  • Anonymous
    January 02, 2013
    I replied at the forum, but here it is again.  Not from what you describe I would expect it to fail identically between the two tools (you can confirm this by looking at the data file you have in both tools).   It is a known issue that for X64 Processes before windows 8 (server 2012), the ETW stack crawling logic stops at the first frame whose code was dynamically generated (that is Just in time compiled).   This issue is fixed in Windows 8.   You can work around the problem by •Running the app as a 32 bit application •NGENing the code you care about. •Run on Windows 8 There is a whole section on this in the PerfView users guide that goes into these mitigations (you can get PerfVIew from www.microsoft.com/.../details.aspx)  See the FAQ or 'BROKEN stacks'.    These mitigations will work for WPR too.  (in general, WPR and PerfView can use each other's data).  

  • Anonymous
    January 21, 2013
    The comment has been removed

  • Anonymous
    January 21, 2013
    I don't quite understand what you mean by 'EventSource is not strongly typed'.   Strong typing was the POINT of EventSource.   What do you mean?

  • Anonymous
    January 21, 2013
    Sorry wrong wording. I mean it is not signed dll. I found solution that, I can take existing EventSource.dll and sign it using ilasm. This lets me use it in BizTalk Orchestrations as well.

  • Anonymous
    February 13, 2013
    I have a question as to how do you register your EventSource derived provider with ETW if not using the PerfView tool. I tried giving a guid as an attribute and use that in logman. That did do the logging, but I did not see my strings in the output. It only shows text like DataSize=32 etc.

  • Anonymous
    February 14, 2013
    EventSources can be registered like any other ETW provider, however Like any other ETW provider it is a pain (you have to create the manifest, compile it with MC.exe link it into a DLL and then register that DLL with the OS).   In the next few weeks I will be blogging about a tool that I call 'EventRegister' that will do all this for you in one step.    Until then you have to wait, or do the steps I outlined above by hand.

  • Anonymous
    March 19, 2013
    Using EventSoource derived provider can we direct the ETW events that are created to the Event Log ?

  • Anonymous
    March 20, 2013
    EventSource is built on top of infrastructure that would allow its events to be sent to the windows Event Log, however to do this you need to register a manifest with a bit more meta-data (called Channels) than is done today.  This is a feature that we will be adding in the near future (out of band with the .NET Framework), but it is not there today.  

  • Anonymous
    July 22, 2013
    The comment has been removed

  • Anonymous
    July 22, 2013
    The comment has been removed

  • Anonymous
    October 20, 2013
    I feel as if this really buries the lead on how this class works: "The ordinal number of logging methods' where a logging method is defined to be a method that returns void." Here's what this actually means:

  1. You must subclass EventSource and define custom logging method that return void. This isn't just a Best Practice that looks "nicer" like the MSDN sample implies, it flat-out doesn't work otherwise.
  2. EventSource wakes up, and reflects through its own class looking for public methods returning void, and numbers them (First method is Event ID 1, Second method is Event ID 2, etc).
  3. You must pass the same number as the one that EventSource decided your method was, or else it gets upset. Free suggestion for .NET 5.0, you could do away with event IDs altogether in the simple case via CallerMemberAttribute, change the signature of WriteEvent to look like this:    void WriteEvent(int data1, [CallerMemberName] string caller = null) Now in WriteEvent, write a method to generate an ID from 0 to 0x10000 based on the caller name. Tada! This class of mistake == removed.

  • Anonymous
    March 13, 2014
    Is there no way to write a unit test that when the EventSource in incorrectly defined throws the exception as detailed in perfview, it is quite annoying to have to run perfview for every change?

  • Anonymous
    March 14, 2014
    The comment has been removed

  • Anonymous
    November 17, 2014
    The comment has been removed

  • Anonymous
    June 05, 2015
    The comment has been removed