Transfer Events & Activity Based Logging using EventSource .net 4.5.1

Logs are never looked at in isolation. If we need to look at the log in order to determine the root cause of a problem then it is a particular scenario that we are interested in. With the great testing efforts we do before releasing a product, there might be still some dormant issues which might have been missed. But since they are not apparent and not very easy to reproduce, we are specially interested in the particular order of operations user performed in order to uncover the dormant issue. We need end-to-end tracing support for our .net applications.

Enterprise applications never work in isolation. We have learnt that there cannot ever be a global enterprise system which deals with everything in the Enterprise. So these applications and machines work together in order to accomplish an enterprise operation. That is why everyone has started talking about enterprise integration, I think this would continue to grow.It is possible that our applications perform great in isolation but there are issues when they work together. The only way to uncover such issues is to use the same logging using some identifiers so that we could correlate these operations to understand the scenario.

ETW has long supported the scenario based logging using Transfer Events. You can even find some reference in Park & Buch's article published in 2007 in msdn magazine. The support is provided through tagging these events with Activity Id. The technology supports a scenario based Id (Activity Id), with a related Activity Id for each event.



When .net framework 4.5 was released, the transfer events were missing from the API. EventSource API is based on Manifest based ETW providers rather than the classic provider (no need to register events at install time). This feature has been there for both of these provider. Since technology already supports it, it was just a matter of time to include the support in the API, and .net 4.5.1 does include that support now.

Improvements in EventSource API to support Transfer Events
In order to support transfer events, Microsoft has provided various little updates in EventSource API in .net 4.5.1. Let's start with the EventSource type itself. In order to identify scenario, EventSource is provided with a new property called CurrentThreadActivity. This can be used as the Activity Id for a particular scenario. This is a read-only property. In order to specify the value, there are two modifier methods. This is one of the biggest improvement in .net framework 4.5.1. This is strategic.



We use WriteEvent() method in [Event] methods in order to write events data to ETW infrastructure. There are two new WriteEvent() methods introduced by the same type to include related Activity Id for the operation. The latter of the following methods provides better performance.



Both of these Ids are available through EventWrittenEventArgs in EventListener's OnEventWritten() method. There are two new properties added to the type. The ActivityId is the same as the CurrentActivityId value for the EventSource when WriteEvent() is called; and RelatedActivityId is the value passed as one of the argument to the method.



Sample Event Source with Transfer Events
Let's create a sample C# application using .net framework 4.5.1. Here we are using Visual Studio 2013 RC. The EventSource has two event methods; one of which is TransferEventEx which uses activity Ids.


And here is an EventListener using AcitivityId and RelatedActivityId from EventWrittenEventArgs.


Now we can use the above EventListener to enable the events written using MyEventSource. First we need to set the ActivityId for the scenario, then we need to specify the operation based Id; used as RelatedActivityId.


Transfer Events for Inter-application Enterprise Scenarios
As stated in the beginning, the real benefit of transfer events can be observed tracing end-to-end scenarios performed across application boundaries. The following is an example of a scenario identified by an Id = X (Activity Id). There are three related activities in the scenario tagged with related activity Id (s) identified with A, B and C. These applications can use ETW for their event logs. For the case of EventSource (manifest based provider), these events can be picked up by a central Semantic Logging Service. The data for these events can be pushed to an event store or any other sink of interest.



Download

EntLib6 Semantic Logging with SQL Server Sink

In the last couple of months we started our discussion about EventSource and Semantic Logging Application Block. You can refer to the previous posts here:

• EventSource & PerfView
• Semantic Out-Process Logging using Semantic Logging Application Block - File Sink
• SLAB - Reactive Event Sourcing
• To Log or Not to Log...Really???
• .net 4.5 EventSource & Windows Event Log - Microsoft's Nuget Package
• EventSource and Implenting Interfaces

In the above posts, we discussed how to create an Event Source and why do we actually need structured logging. We presented some examples of consuming the events generated by EventSource using tools including PerfView and SLAB's Semantic Logging Service. Event Sinks and listeners allow us to consume those events and pushed them out externally, including file system and Windows Event log. This post is about taking the discussion a little further to see how we can push out the events generated using an EventSource to SQL Server Database.

System Requirements
SLAB supports SQL Server 2008 and higher, SQL Server LocalDB and Windows Azure SQL Database. We will be using SQL Server Local DB for this example.

Sample Event Source
Let's create a sample console application SLABSqlEventSinkEx. We add the following EventSource to the project.


Let's try to verify if our EventSource has no issues by using PerfView. We discussed about using PerfView for ETW events here.


And we do see the event being generated. Please notice the selection below:



SLAB provides a number of Event sinks. Not all of them are in the same assembly.



Pattern & Practices team has distributed them among different Nuget packages. If you want to utilize the events generated by an event source and push them out to a SQL Server database then you would need to use the following package:



After packages installation, this is how my packages.config looks like.


Creating Database
The nuget package provides the necessary script to create database schema. We can find the scripts under ...\packages\EnterpriseLibrary.SemanticLogging.Database.1.0.1304.0\scripts folder. Just run the cmd file in the folder. It should run both sql files passing the required parameters.



The script creates a new database Logging with a single table, stored procedure and a couple of user defined types. It assumes installation of SqlLocalDB installation. Here we have connected with the database using Visual Studio SQL Server Object Explorer in Visual Studio 2012.



We can use SqlLocalDB command line tool to check the state of sql server instance used.



If you are using out-proc Semantic Logging Service to consume the events then you really don't need to download the package. The script and command file is copied into the service's folder when you install the nuget package. You can find them here:



Using SQL Server Sink with Semantic Logging Service
As we have discussed before SLAB allows us for out-proc logging using Semantic Logging Service. The service can run as a console application or windows service. You can see the this post where we introduced the service and its use with file system sink for event sources. Let's update the service configuration [SemanticLogging-svc.xml] to push the events from SqlApplicationEventSource to SQL Server database created above.


After updating the configuration, we can run the service as a console application as follows:



Run the application writing ETW Events. As the events are pushed out, the service writes the details to the specified database. Here is the same data as we saw in PerfView earlier in this post.



Using SLAB's In-Proc SQL Server Sink
We can also enable the events In-Proc. SqlDatabaselog can be used to create the listener to be used to enable the events. We can add the following code to the Main method of our console application created above.


But I have noticed an issue logging the data in SQL Server. I have discussed the issue here: [Discussion about Keyword issue]. The issue is based on using Keyword with the event method, which might seems related.

Download

[Resolved] Issue with EventListener.OnEventWritten when used In-Proc

Finally I was able to trace the issue why my In-Proc EventListener's OnEventWritten was not being called. In order to understand it let's create a sample console application targeting .net framework 4.5.



Let's add a simple method to write event when a request is received for password hashing. It has an EventId set as 1.


Now add an event listener as follows:


Now let's first enable the events for the listener after instantiating this. We can now call the EventSource method to write event data. When we run this EventListener's OnEventSourceCreated does get called but there is never a call for OnEventWritten when the event data is written. If we set a breakpoint there, it never gets hit.


Now let's change the code a little and remove the keyword detail decoration from the EventSource's method as follows:



Without changing anything else, let's run the application again. Now we notice that the break point in MyEventListener.OnEventWritten does get hit.



Connect Issue
I have logged an issue here on Connect. Let's see if we are missing something here:



Resolution
In order to enable events by the listener, we need to be clearly specifying the keywords we are interested in. There can be more than one keywords used with bit masking (that's why the keywords should have enumeration values in the power of 2). We can also enable the listener for all keywords using Keywords.All. [Thanks, Alex Ghiondea!]


Download