The EventSource NuGet package and support for the Windows Event Log (Channel Support)


One of the more common questions we get about the System.Diagnostics.Tracing.EventSource class is whether it can be used to log message to the

Windows Event Log (that is can be viewed with eventvwr.exe).   This EventLog support is also called ‘Channel support’ because that is the official name for a ‘stream of events’ in the Windows event log. 

The answer to whether EventSource supports the Windows Event log as a target has been ‘no’ but now the answer is ‘yes’.    Moreover, you don’t even have to wait for the next version of the .NET Framework to get it.

That is because we have now created a ‘Stand alone’ version of EventSource and published as the Microsoft EventSource Library NuGet Package (currently in Prerelease form, so you have to set your filtering to include prereleases to see it).    Note that the class in this package is in a different namespace Microsoft.Diagnostics.Tracing.EventSource, so it is ‘side by side’ with System.Diagnostics.Tracing.EventSource that comes with the V4.5 framework.   It is however intended to be 100% compatible with code using the framework version.   It is also effectively your way of getting at new features of the framework version before they are officially released (or your customers have upgraded their framework).    Switching from one to the other should be as easy as changing a ‘Using’ declaration at the top of the file that uses EvenSource. 

Thus Windows Event Log support is just the first installment of new features that we will be bringing to you through NuGet as a way of getting started now without having to wait for the next version of the runtime. 

To see more details about the Event Log support see the dotnet Blog entry ‘Announcing the EventSource NuGet Package : Write to the Windows Event Log’.

Along with the Microsoft EventSource Library NuGet Package, there is also the Microsoft EventSource Library Samples NuGet Package.   This package makes it very easy to download some working EventSource code and see well commented examples of its use.  The best way to use this samples package is to

  • Create a new Console Application in Visual Studio called ‘DemoEventSource’
  • Reference the Microsoft EventSource Library Samples NuGet Package from this new project by
    • Right clicking on the ‘References node in the Project tree
    • Selecting ‘Manage NuGet Packages
    • Searching for ‘EventSource Samples’
    • Selecting the Microsoft EventSource Library Samples package
  • It will download some code to a ‘EventSourceSamples directory, which you look at
  • You run the code by adding the following line to your main program
    • EventSourceSamples.AllSamples.Run();
  • Hit F5.  

Some of the samples are very similar to samples I have blogged about in the past, but the Window Event Log sample is new.   It is also more complex because there is a registration (install time) step with the operating system.   This is the price you pay for wanting your messages to get to the Windows EventLog.  

Finally, also included in both packages is a EventSource Users Guide.   This contains information similar to things I have blogged about, as well as best practices etc.   Note that the previous link (as the file in this blog) may not be up to date.  The most up to date version is in the Microsoft EventSource Library NuGet Package

 

Vance

 

 

_EventSourceUsersGuide.docx

Comments (40)

  1. Hi Vance.

    Thanks for your amazing work on the ETW support for .NET Framework.

    There are a few problems that we encounter while using EventSource and TraceEvent libraries in our application.

    When using the `params` overload of the `WriteEvent` method, passing `null` to one of the string parameters causes the call to silently fail. Consider this class:

    class MyEventSource : EventSource

    {

    public static readonly MyEventSource Log = new MyEventSource();

    public void Write(string userName, int i, string text)

    {

    WriteEvent(1, UserName, i, text);

    }

    }

    This will fall back to the `params` overload of the `WriteEvent`. If we do:

    MyEventSource.Log.Write(null, 1, "this is a text");

    the event will not be sent, while if we remove the int parameter (that uses one of the non-params overloads) the call will succeed. I've tested this in the latest version of the EventSource nuget package (1.0.6-beta) and the problem still exists.

    Thanks

  2. Strange thing is that calling both

    MyEventSource.Log.Write(null, 1, "text");

    and

    MyEventSource.Log.Write("user1", 1, null);

    fails in nuget package version, but in .NET 4.5 version only the first call fails!

  3. The basic answer to your question is that passing null to an WriteEvent method is illegal.   This can be inconvenient for some cases where strings are passed, there are a number of problems with making WriteEvent do something with null strings (most noteably is that ETW does not define a serialization for the null string).    

    Our advice is that if you need to pass null strings to your logging functions that you do the null check in your helper routine using the ?? operator.  

    public void Write(string userName, int i, string text) {

       WriteEvent(1, UserName??"", i, text);

    }

  4. Thanks for your answer Vance.

    This is what I do now, but it took me some time (almost a day) to debug the EventSource source code (using .NET Reflector VS Add-In) and find the reason for not sending the event when I add an `int` parameter to my event method! (No relevant, but my situation was a little complicated because we are creating EventSources dynamically using dynamic assembly generation and Emit) The inconsistent behavior is what mostly I'm complaining about. By the way, I'm very thankful for your great job.

    Another problem we have is that we cannot receive events from an EventSource by two separate sessions at the same time when one of the sessions are started *after* the creation of the EventSource. The second session receives the events as *unhandled events*. The event ID and other data are correct, but it does not contain the event name and parsed payload data.

    What I found so far is that the manifest data is sent only for the first session, so the second session knows nothing about the structure of the events.

    I'm trying to solve this problem by manually sending the manifest data (calling EventSource.SendManifest method) every time the EventSource is being enabled by a session. What do you recommend?

  5. Oh! Sorry!

    I was using the .NET 4.5 version. The problem is fixed in the latest version (Nuget package). I forgot to test my second problem with new version.

    After 2 days of investigation, and fixing the problem my own way, I found that it is already fixed in the new version!

    Thanks again!

  6. I have been having some problems with registering the ETW Manifest files.  When I built my sample in My DocumentsVisual Studio 2012Project… I got this error:

    **** Warning: Publisher Blah-Blah-Blah esources are not accessible.

    Saw something on the web about paths too long so moved the solution to C:Temp. Now it registers without error but the corresponding logs aren't created.  When I check with wevtutil gp Blah-Blah-Blah, I get:

    name: Blah-Blah-Blah

    guid: e71f8805-84a4-502f-4fe9-54cc01066a60

    Failed to get helpLink property. The specified image file did not contain a resource section.

    FWIW if I open the manifest DLL I see two resource sections: 11 and "WEVT_TEMPLATE". I am targeting .NET 4.0.  And just tried .NET 4.5 – same error.  What could I be doing wrong?

  7. Nevermind.  Pilot error on the wevtutil.exe im invocation.  I had the .man file as the /mf: parameter.  Also you have to apparently stop & restart the computer management console in order to see the new log.

  8. BTW why do my EventChannel.Admin log entries have Keywords set to:

    Session0,Session1,Session2,Session3

    I did not specify these in the corresponding attribute. Where is this value coming from?

  9. The short answer, is that these are internal keywords reserved for EventSoruce/Session communication.  

    The longer answer is that EventSource supports passing extra parameters from the session to the EventSource to specify more precisely than Keywords can which events a particular session wants.   Sadly ETW's support for this is incomplete and two session using this technique may interfere (sessions might see events that were intended for the other session).   EventSource fixes this by reserving some of the keywords (those 4 shown above), to represent up to  4 sessions that an event might be destined for.   This allows each session to only receive the events that they actually turned on.    

  10. Thanks for the clarification on the use of Keywords by EventSource.  

    BTW I was somewhat surprised that I could export the event log to file and read it on another machine and have all the custom message formatting strings appear on the other machine where I hadn't registered the ETW manifest.  Is this more of the EventSource magic of inline manifests?

  11. When you say 'log file' I assume you mean ETL file. and the tools you are referring to are either PerfView or WPA then yes, that is by design.   EventSources log their manifest to the event stream so that the ETL file is self-describing (they way it always should have been).   Note that other Providers besides Evensources can do this (it is a contract between providers and consumers).    

  12. Actually I'm referring to an EVTX file created by the Windows EventViewer.  That loaded up on another machine I couldn't tell a diference.  All my custom formatted "Messages" appear just fine there.  I wasn't expecting that to work since the manifest wasn't installed on the other machine.

  13. I don't have any insight into EVTX files, but clearly they store the formatted information and not the raw information (which is the right thing to do).

  14. I'm using this drop in a .NET 4.0 application but I'm having trouble getting PerfView to give me DURATION_MSEC information even though I'm using the attribute values:

    [Event(…, Task = Tasks.ParseMessages, Opcode = EventOpcode.Start)]

    and

    [Event(…, Task = Tasks.ParseMessages, Opcode = EventOpcode.Stop)]

    What I find is that if I specify no parameters to some of my start/stop methods I get DURATION_MSEC in PerfView.  However in some case (like Tasks.ParseHeaders) I don't have the parsed header until I hit the Stop method. So the ParseHeadersStart() event source call takes no parameters and the ParseHeadersStop(string header) takes on parameter.  I several Start/Stop pairs like this that only have a parameter in the Stop method.  None of the give timing info i.e. DURATION_MSEC.  I haven't quite figured out the magic of getting correlation (ActivityID) to work with EventSource.  Is there something I'm missing?

  15. The issue with computing durations is that many starts and stops might be in flight at the same time.   Thus you need something 'id' that allows you to 'link up' start and stop events unambiguously.    PerfView has some heuristics, but if you make the first field in your Start and Stop event be an ID that uniquely identifies the start-stop pair, then PerfView should produce the DURATION_MSEC

  16. In section 5.6.2.2 of the spec, it would be helpful to give a WriteEventCore example that takes a string argument.  When getting a pointer to the string, do we need to marshal the string to HGlobalAnsi string?

  17. Vance Morrison says:

    Here is an example of using EventWriteCore to write a string and an integer argument   This code is very similar to some of the type specific WriteEvent() classes that are shipped in the library.

    Basically you use the 'fixed' statement to pin the string, stack allocate the descriptors needed and call the core function with the descriptors of the arguments.  You can have several nested fixed statements if you want to pass multiple strings.   Notice that the string length includes a null terminator which is part of every .NET string.

           unsafe void WriteEvent(int eventId, string arg1, int arg2)

           {

               fixed (char* string1Bytes = arg1)

               {

                   EventSource.EventData* descrs = stackalloc EventSource.EventData[2];

                   descrs[0].DataPointer = (IntPtr)string1Bytes;

                   descrs[0].Size = ((arg1.Length + 1) * 2);

                   descrs[1].DataPointer = (IntPtr)(&arg2);

                   descrs[1].Size = 4;

                   WriteEventCore(eventId, 2, descrs);

               }

           }

  18. >> PerfView has some heuristics, but if you make the first field in your Start and Stop event

    >> be an ID that uniquely identifies the start-stop pair,

    I've noticed that Start/Stop WriteEvent() calls with no parameters seem to pair up correctly in PerfView.  But I'm thinking I should not rely on that and should pass in a unique ID anyway, right?  

    BTW, one enhancement request is that it would be nice to have a WriteEvent overload that supports a string parameter(s) but with an int parameter (for this start/stop pairing ID) right after the eventId parameter and before the string parameter(s).  Hence my question about passing strings into WriteEventCore.  🙂

  19. PerfView uses the ActivityID and if that is not present the thread ID as the coorelationID for start and stop if you dont' provide one.   ActtivityID could be 'perfect' and ultimately would probably be enough, but in the short term having an ID is definitely a good idea.

  20. Just to be clear, there is no way using the current EventSource implementation for clients to specify the ActivityId. That seems to be an internal detail and it kind of looks like it is passing a null Guid*.  I guess that is why it is best to use our own ID.

  21. You can specify an Activity ID with the Nuget version of the EventSource.  See the SetCurrentThreadActivityId API.   However you can do more harm than good if you set ActivityIds without a clear understanding of how they should be used (you can clobber some other code that WAS using them correctly).   If you goal is simply to hook up start and end events, it is better to use an ID (also ActivityIDs are not guaranteed to be enough, since you could start two tasks on one thread, but complete them on two different threads 'caused' by that activity.   In that case, activity IDs are not sufficient to disambiguate.   Thus it is really not bad to have an ID for a start and stop event EVEN IF you also use activities IDS.  Ultimately they are for different purposes.  

  22. Paul Ballarin says:

    Can you implement AppFabric-enabled WCF Data Service as show in Ron Jacobs excellent blog post but with the new .Net 4.5  EventSource infrastructure?

  23. Vance Morrison says:

    Sound a bit outside the scope of the EventSource package.  

  24. Anton says:

    It seems to me I don't completely understand the mean of WriteEventWithRelatedActivityId method and the "relatedActivityId" parameter. Correct me please if I'm wrong.

    Assume I have two components – A and B. Component A is an infrastructure component and has some entry point (receives messages from some transport and dispatches them to component B. Because it's real entry point of a whole application component A assigns ActivityIDs at the begining of its message processing pipeline. Assume component B wants for some reasons to have its own ActivityIDs for its tasks.

    Assume that component B works in the same thread with component A.

    1. It should get and store component A's ActivityId, set new ActivityId to the thread and write some transfer event:

    Guid relatedActivityId;

    ComponentBEventSource.SetCurrentThreadActivityId(Guid.NewGuid(), out relatedActivityId);

    Log.WriteEventWithRelatedActivityId(eventId, relatedActivityId, …)

    2. When component B's part of work is completed it should simply restore component A's ActivityID:

    ComponentBEventSource.SetCurrentThreadActivityId(relatedActivityId)

    Is it correct usage?

    In the case when components A and B work in different threads or even in different processes on different computers I should simply send original ActivityId (may be "over the wire") to the component B and write transfer event on the conponent B's side in order to provide end-to-end tracing. Of course step 2 is not required in this case.

    Is it correct?

    So I initially consider "relatedActivityId" as activityId of the "parent" or previous component's activity. But when I was looking for examples in .NET BCL I found TPL is instrumented with EventSource. And I see you use "relatedActivityId" as activityId of the child activities. So the parent component writes transfer events. In TPL it's possible thanks to the fact that parent component knows child activityId (it's explicitly constructed from TaskId). Child component still have to replace current thread's activityId and then restore it.

    And so I came to the conclusion that both possible. And usage style depends on the specific solution context. From the events consumer's point of view it will be not too complex to recognize what pattern was used by component's developers and to perform end-to-end trace analysis.

    Is it correct from Microsoft point of view? Are there any other considerations?

  25. I will write a more tutorial blog about this, but here is a quick answer

    First Generally speaking unless YOUR component causes activities to 'hop threads' (you are implementing a threadpool or you are making cross process calls  using APIs that don't already take activities into account)  Thus generally speaking we don't expect non-Microsoft people to use SetCurrentThreadActivityId.

    The reason of this is because as you point out if activities nest (which they do, very commonly), you have a problem because a thread can only have one activity ID at a time.  At a minimum if you SET the activity ID you have to RESTORE it before returning from your code (since your caller in general will NOT assume that it has been changed by you).   However we like to believe that users DON'T need to do this because you can compute your activity from the activity IDs that are ALREADY logged by the Task library.     In fact that current TraceEvent library (on http://www.Nuget.org), has support for this (we only have minimal docs on it right now).  

    As to the question of related Activity ID.   As you have learned, it is valuable to sometimes be the 'causer' and sometimes be the 'caused' activity.  (That is why it is not given a better name, sometimes its one thing and sometimes its another).   The convention that we used for the Task library is that determine which way by looking at the OPCODE of the event that logged it.   If the opcode is 'SEND" then the current activity is the sender and thus the related activity is the 'caused' activity.   If the opcode is 'RECIEVE' then the current activity is the receiver and thus the related activity is the 'causer.

    But my general advice is to do neither.   You are not implementing a threadpool so you don't need to set activities, you should just be 'inheriting the ones you get from the Task library.  

    So what should you do?   You should create Start and Stop events for what you are probably calling activities today.  Start and stop events CAN nest (many can be live concurrently.   When you turn on your events as well as the Task Library events, you can get a complete picture of all the activity that was logically 'caused' by the start event (which is what you are after).    You probably also want to give your start and stop events an correlation ID (some number that represents the activity that can be used to pair up the starts and stops.  This way you can use your events without needing the TPL events as well.  

  26. Anton says:

    Thanks for the answer, Vance!

    I now understand that ActivityID management is the highest (or lowest :)) level of correlation for end-to-end trace analysis. It's usually should be implemented by the infrastucture libraries that relate to the threadtask management (TPL) or to the external boundaries of the applications where the application's global "unit of work" starts to live or jumps to the other applicationscomponents (infrastructures like IISASP.NET, WCF and so on). These libraries should assign initial ActivityID for every global "unit of work" and then should write transfer events in the cases of any threadprocessmachine jump or "sub task" starting (for example when I start several parallel TPL task inside global "unit of work"). ActivityID relates only to cross-thread and processmachine correlation (if communication infrastructure supports it. Like SQLServer TDS protocol that transfers activityID from the client to the server and than writes it to some of SQLServer "extended events"). This infrastructure ActivityID management if present is ALWAYS sufficient . But for my convenience I can decide to add additional correlation data.

    But really… Where I can hope that cross-cutting ActivityID management will be in place? If I write my ETW events inside IIS8.5 integrated pipeline. Can I see end-to-end request tracing including my events?

  27. Indeed you do seem to understood the basics of how activity IDs need to work.

    As you your question about when Activity ID management will be in place, it is indeed coming, but it will come in phases over time.   Already some support is already in place (the TPL events for instance), and some rudimentary support is available in some libraries and tools (e.g. TraceEvent and PerfView), and more is coming.  There is work in App Insights and VS tooling in this area.  

    I would like to flip the question around.   You were about to add ActivityID code to your library/app.  What exactly where you hoping to get from it?    What tool or library (or whatever) were you expecting to 'light up'?  and in what way (how did you expect your events to be displayed in that tool).    What exactly do you mean by 'ActivityID management'?   At one level, we do have the most important basic plumbing of an end-to-end activity management system in place (e.g. the TPL events are there and added the SetCurrentThreadActivityId which allow us to instrument the rest of the framework), and we are moving up the stack, making infrastructure that can process this activity information.    Thus we are executing on a plan.    But realistically a really good end-to-end story is many months off.   However it is possible and event likely that you can get 'good enough' solutions that will tide you over much more quickly, depending on exactly what you need most critically.   Thus having some idea what you want and what the priorities of each of those desires is would be helpful.  

    Finally one last point.   While we can commiserate about the current level of support for activities, what is definitely true is that a certain amount of instrumentation on your part (start and stop event of the time periods that are most critical to you) is part of the long term plan, and YOU CAN GET VALUE from the IMMEDIATELY (you can do light weight, monitoring)    Thus getting 'your part' of the plan done is a clear first step.  

  28. RobV8R says:

    We also use Activity IDs and Related Activity IDs to correlate events.  Most of our routine EventSource logging occurs in the Windows Event Log.  We log very high level informational events and as much information about errors as we can.

    We accomplish this using the NuGet package's "Channel" support.  Unfortunately, when we doe this, the Windows Event Log doesn't record the Activity ID at all.  Oddly, it DOES record Related Activity IDs.

    For a given EventLog entry produced by the NuGet package's Channel support, if you do not specify a Related Activity ID, the Correlation element will be empty.

    – <Event xmlns="schemas.microsoft.com/…/event">

    – <System>

     <Provider Name="MyApplication" Guid="{012345678-9ABC-DEF0-1234-56789ABCDEF0}" />

     <EventID>1</EventID>

     …elements ommitted for readability

     <Correlation />

     </System>

     </Event>

    If you specify a Related Activity ID, the Correlation element will contain only the Related Activity ID.

    – <Event xmlns="schemas.microsoft.com/…/event">

    – <System>

     <Provider Name="MyApplication" Guid="{012345678-9ABC-DEF0-1234-56789ABCDEF0}" />

     <EventID>1</EventID>

     …elements ommitted for readability

     <Correlation RelatedActivityID="{F12345678-9ABC-DEF0-1234-56789ABCDEF0}"/>

     </System>

     </Event>

    I would expect that the Activity ID would ALWAYS be recorded in Correlation/@ActivityID.

    Vance, if you read this, I can provide simple example projects.  

    If anyone else has had a different experience than I've described above, please speak up and tell me how you did it.  I'm not afraid to admit when I'm wrong.

    Thanks,

    Rob

  29. RobV8r says:

    I haven't seen any feedback on this.  I'm beginning to use tools like Microsoft Message Analyzer and PerfView.  The lack of an Activity ID prevents many features from working such as Call Stacks.  Any advice is welcomed.

  30. Are you saying that when you log with your EventSource (and send it to an ETL file) do you see both the ActivityID and RelatedActivityID when you view it with WPA or PerfView, but not when you look in the windows Event viewer (the windows EventLog)?    This is surprising.   This may be a bug in the OS;s EventWriteTransfer API.  It is supposed to get the activity ID from thread local storage if you don't pass an activity ID explicitly (which it seems to do properly for ETL files), but I wonder if it fails to do that when sending the data to the Windows Event Log.  

    Can you work-around this by simply passing the activity ID as some other payload field.  

  31. winterTTr says:

    Hi Vance Morrison,

    Not sure if this the right place for asking question about ETW on Azure.

    When I use ETW within the Azure Cloud Service, I recorded event with WriteEventWithRelatedActivityIdCore, the etw result in the Azure Cloud Service Storage do not include the "RelatedActivityId" column. Is this the default behavoir of azure diagnostics logging sink? Is this behavior could be customized?

    BTW, I can see those columns when I use PerfView.

  32. If you see the columns in PerfView, it means that the RelatedActivityID is actually being written out properly.   To be able to comment more, I would need to know more specifics on what service is listening and copying your events (Is it WADS?).     This is more properly a question to that team.  

  33. winterTTr says:

    Thanks very much for your quick reply.

    Yes, i think it should be WAD( windows azure diagnostics )

    Originally, i think something from ETW side may be customised to give some impact  to the output result. So from your comment, i think if the information is already in ETW when i use perf, the final output would be the responsibilty of WAD. I would dive more info about WAD. Thanks very much.

    One more thing I want to confirm, when I use 'EventSourceAnalyzer.InspectAll' to check the event source implementation, i found that I have to implement my own WriteEvent of pass the check. If i use the WriteEventWithRelatedActivityId directly in a custom event, such as "DBFailed" like this:

    [Event(someid)]

    public void DBFailed(string payload)

    {

       var relatedActivityId = TryToGetThisId();

       WriteEventWithRelatedActivityId(someid, relatedActivityId, payload);

    }

    It seems the EventSourceAnalyzer.InspectAll will report the write event parameter count is not the same as event define. So I have to implement my own "WriteEvent" to pass the check.

    I want to confirm here if it is by design? Or I make a mistake somewhere?

    -winterTTr

  34. ranta says:

    The ReportEvent page in MSDN Library now mentions that an explicit format specifier like "%1!S!" in the event message prevents Event Viewer from treating percent signs in the corresponding insertion string as references to strings defined in the ParameterMessageFile. Should ManifestBuilder.TranslateToManifestConvention add those format specifiers?

  35. @ranta:  Can you point me at the ReportEvent Page you reference.  Also can you be more explicit about what 'goes wrong' with the current implementation?   Are you sawing ETW will interpret % a string that was SUBSITUTED in a %1 format specification as ANOTHER format specification!  

  36. ranta says:

    "If the string that you log contains %n, where n is an integer value (for example, %1), the event viewer treats it as an insertion string. Because an IPv6 address can contain this character sequence, you must provide a format specifier (!S!) to log an event message that contains an IPv6 address. This specifier tells the formatting code to use the string literally and not perform any further expansions (for example, "my IPv6 address is: %1!S!")."

    In contrast, the same topic in Visual Studio 2008 documentation (Build date: 8/15/2007) said:

    "Note that there is no way to log a string that contains %n, where n is an integer value. This syntax is used in IPv6 addresses, so it is a problem to log an event message that contains an IPv6 address. For example, if the message text contains %1, the event viewer treats it as an insertion string."

    I tested it a bit on Windows 7 SP1 by running this command as administrator:

    EVENTCREATE /ID 1 /L Application /SO RecursiveExpansionTest /T INFORMATION /D "{{%1}}, [[%1!s!]], ((%1!S!))"

    This command registered "RecursiveExpansionTest" as an event source with EventMessageFile = REG_EXPAND_SZ "%SystemRoot%System32EventCreate.exe", in which each entry of the message table contains only "%1" and a newline. I then opened Event Viewer, in which XML View displayed the EventData as follows:

     <EventData>

       <Data>{{%1}}, [[%1!s!]], ((%1!S!))</Data>

     </EventData>

    The General tab of Event Viewer expanded the event to:

    {{{{{{{{%1}}, [[%1!s!]], ((%1!S!))}}, [[{{%1}}, [[%1!s!]], ((%1!S!))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))}}, [[{{{{%1}}, [[%1!s!]], ((%1!S!))}}, [[{{%1}}, [[%1!s!]], ((%1!S!))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))}}, [[{{{{{{%1}}, [[%1!s!]], ((%1!S!))}}, [[{{%1}}, [[%1!s!]], ((%1!S!))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))}}, [[{{{{%1}}, [[%1!s!]], ((%1!S!))}}, [[{{%1}}, [[%1!s!]], ((%1!S!))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))!s!]], (({{%1}}, [[%1!s!]], ((%1!S!))))

    Clearly, Event Viewer recognized the "%1" in the insertion string and further expanded it.

    I did not test the %%number syntax and ParameterMessageFile.

    I did not test "%1!s!" and "%1!S!" in the message table.

    I did not test using the ETW API instead of ReportEvent.

  37. ranta says:

    The page is "ReportEvent function (Windows)" msdn.microsoft.com/…/aa363679%28v=vs.85%29.aspx

    As a programmer, I don't think it is useful that Event Viewer scans insertion strings for references to more insertion strings, but that's what it does so I'll have to cope with it. References to ParameterMessageFile are more useful — or at least would be if there were a public ParameterMessageFile for looking up Win32 error codes. Those are now in kernel32.dll but I don't think Microsoft has ever documented that, so it's subject to change. In Windows 7 and later though, I think I could instead use template/data/@outType="win:Win32Error" in an instrumentation manifest and not have to refer to a specific file.

    If "%1!S!" indeed prevents expansion of the %number (insertion string) and %%number (parameter message) syntaxes, that's nice, but I'll have to test with a few versions of Windows before I dare use that.

  38. ranta says:

    I tested a similar thing using the EventSource 1.1.28 NuGet packages on Windows 7. The repeated expansion happens there too.  I built the following program:

    namespace TestEventLogRecursiveExpansion

    {

       using Microsoft.Diagnostics.Tracing;

       internal class Program

       {

           private static void Main(string[] args)

           {

               using (var eventSource = new TestEventSource())

               {

                   eventSource.Demo1("one: 2=[%2]", "two");

               }

           }

       }

       [EventSource(Name = "Test-EventLog-RecursiveExpansion")]

       internal sealed class TestEventSource : EventSource

       {

           [Event(1, Channel = EventChannel.Admin, Level = EventLevel.Informational, Message = "Demo1: arg1=[{0}], arg2=[{1}]")]

           public void Demo1(string arg1, string arg2)

           {

               this.WriteEvent(1, arg1, arg2);

           }

       }

    }

    I then registered the manifest using "wevtutil im", and ran the program. Event Viewer displayed "Demo1: arg=[one: 2=[two]], arg2=[two]". I would have preferred "Demo1: arg=[one: 2=[%2]], arg2=[two]".

    Next, I unregistered the manifest and edited it, changing this part

      <string id="event_Demo1" value="Demo1: arg1=[%1], arg2=[%2]"/>

    to the following:

      <string id="event_Demo1" value="Demo1: arg1=[%1!S!], arg2=[%2!S!]"/>

    I compiled the manifest to a DLL using "eventRegister.exe -CompileManifest", registered it again using "wevtutil im", and restarted Event Viewer. Now it displayed "Demo1: arg1=[one: 2=[%2]], arg2=[two]".

    Finally, I unregistered, edited, compiled, and registered the manifest again, but this time with lower-case "%1!s!" and "%2!s!". Event Viewer again displayed "Demo1: arg1=[one: 2=[two]], arg2=[two]". It appears that only an upper-case "!S!" prevents nested expansion.

    Thus, I think ManifestBuilder.TranslateToManifestConvention should indeed be changed to emit "%1!S!" rather than "%1", so that IPv6 addresses with scope identifiers can be safely logged.

  39. I have passed this along to the owner of the code.   I agree it is a good change.

    1. vijay says:

      Hi Vance,

      This was really helpful information to log to windows event log.
      I have got a use case where I need to have a my own defined channel .For example , I have many plugins trying to use my library to log to windows event log.I need to separate these plugins under my folder MyCompany/MyApp/Plugin1 or MyCompany/MyApp/Plugin2 instead MyCompany/MyApp/Admin(or Operational or Debug or Analytic).
      Is this possible ?