SLAB, EventSource and Standard ETW Tools

As we have been discussing through the past few posts that we can direct event log data generated through EventSource to be saved in different destinations. EntLib6 provides a number of sinks provided just for that purpose out of the box. They include support for console, files, Sql Server database and Windows Azure Table storage. We have also seen how we can direct the event's data to Windows Event Log [Discussion]. It would be interesting to see how we can use the existing ETW tools to view the event's data generated using EventSource API in .net framework 4.5.

EventSource API is based on registration free ETW [Event Tracing for Windows] data. This means we don't have to register an ETW event provider for generation and consumption of these events. The existing tools including LogMan and Windows Performance Analyzer are based on registered event providers. But since EventSource API is still based on the same ETW infrastructure, we can register the Event Provider manually and direct the events' data to an ETL file. Since these tools can work with this format, we can use our expertise in these tools to troubleshoot and analyzer situations we need this data for.

It must be remembered that EventSource API uses ETW infrastructure only in the case of out-proc listeners.

Performance Monitor [Perfmon.exe]
Since EventSource establishes an ETW session for out-proc consumers, we should be able to use PerfMon to see the details of the session.



As an ETW provider, each event source is assigned with a GUID. We can note the unique identifier from the properties of the provider. This identifier is generally used by ETW controllers to start / stop a session. We can also verify that the streaming mode for the configured EventSource as Real time.



PerfMonitor.exe
Like PerfView, PerfMonitor is also based on TraceEvent library. The major benefit of PerfMonitor over Perfmon is that the former can be used as an ETW controller.



https://bcl.codeplex.com/releases/view/99985

Logman
Internally Logman seems to use Performance Logs & Alerts service. If the service is not running, the utility just starts this. Make sure that we are running the command prompt with Administrative privileges.



Here we are creating a trace data collector using Logman utility.


After running the above command, we should be able to find the specified collector when queried. This can also be done using Logman. The utility supports a verb "query" which list all the data collectors.



We need to start the data collection for the events generated from the event provider. In order to do that we can use Logman's start verb with the provider's name as follows:

Querying the provider again should show the status of the provider as Running. This should ensure that the command ran successfully.



Stopping the trace session should flush the trace data in the ETL file. Here is the file generated for our provider in the same folder as we specified while creating trace data collection for the provider.



Logman also registers a user-defined trace which can be viewed with Performance Monitor.



Tracerpt
This is another useful Windows Utility for ETW data. One of the usage for this utility could be to process the ETL files generated using any other tool. It can be used to generate human readable files from the binary data. Let's see the following usage:


The above command should generate dumpfile.xml and summary.txt in the same folder. For the events generated for our event provider, the following files are generated. You can open them to have an idea about the expected format for the generated files. We should note that the utility allows us to control the names and format of dump and summary file names and formats. The supported formats for dump file include XML (default), CSV and EVTX.

  

We can also generate xml (default) or html based report for the generated events data. Here we are generating the report in html format. It generates the report based on the etl file provided in the same command.


You can have a look at the following report generated for events generated from our event source.



Tracerpt can also use ETW data from real time sessions. We can use PerfMon to determine the session we are interested in. We can then use the same name with -rt switch for TraceRpt. Here is the session details for our event source.

EntLib6 - EventSource & Keywords for Semantic Logs

In this post we are going to discuss two very common details for defining event source. They are EventLevel and EventKeyword. They are so central for defining and enabling events. Yet, it is very easy to make mistake in using or expecting a particular behavior with the values used for them. The value assigned to them might include other values as well, which might come as a surprise for others.

Event Level
As we discussed, the event level selected for enabling a listener is the maximum value of the level which would be forwarded to the subscribed sinks. All events assigned with levels equal or lesser than the assigned enumeration values are considered enabled.

I have really felt that intellisence is not really useful in this case. The levels are ordered in the ascending order of their names. It could have been really useful if they could be available in the order of their values [but there are some things in life you cannot get, hence the void... :)]



Let us try to make it a little easier. We can come up with an acronym like from top to bottom, it is VIWECL. In order to remember this, we can come up with some catchy phrase like Very Intelligent Wife so Extremely Cool Life. Here whatever level we specify to enable the event source, all the lower levels are automatically included. I think we should not forget it now. When someone special is involved, it is better to try not to forget...



Keywords As Power of 2
It must be remembered that keywords must be assigned values in power of 2. It makes it easier to enable and disable the events. Here is an inner class Keywords defined in an EventSource. You can see that the values are 1, 2, 4, 8. They are powers of 0, 1, 2, 3 respectively.


In order to understand how we can use these keywords, we need to understand the bit mask for these keywords. We have the bit masks for Creation, AdmissionApproved, FeeDeposited and TransferCreditHours.



Definition of EventSource
Let us introduce an EventSource. The event source has four [Event] based methods. The methods are using the values of keywords defined above. They are also assigned with particular


Special Event Level & Keyword
EventLevel.LogAlways has special meaning when we use it to enable the events. It means to ignore levels when filtering is being applied i.e. all levels are considered. Since this is a perfectly fine EventLevel value which could be assigned to an Event method, it might get confusing when you would just want to enable the events assigned to this level, as it has a specific mean in this scenario. I think we should better avoid it when defining our events. I still have this in my EventSource just to give you an example.

Similar is the case for Keywords.All. It means to include all keywords. Basically, when we don't specify an Keyword to enable a scenario, all those events which are assigned with a specific value of keywords are just ignored. If we want to consider all of them instead, we can use this value for EventKeyword when enabling events. It has a value -1. We can use this value for enabling all keywords with xml configuration in the case of Semantic Logging Service configuration.

Configuration for In-Proc usage
As we have discussed before we can use SLAB both In-Proc and Out-Proc scenarios. For the In-Proc scenarios, we can enable the events using ObservableEventListener specifying the details of event's levels and keywords we are specially interested in. Let's first consider the case of specials for level and keyword. Here we are using EventLevel.Always and Keyword.All, which means to say, I want to log everything.


And it does have all the logs, no matter what Level or Keywords they are assigned with. Here is the output for the above code:



EventLevel.LogAlways with other keywords
Let's see the following combination. Here we are using EventLevel.LogAlways with two keywords.


If you go back and look at the definition of our EventSource, we don't have this combination of Level and Keywords for any event. There is only one event with Level assigned as EventLevel.LogAlways, but that has different keyword assigned.

So does it mean, it should include none of the events? Acutally No!!!

As we have discussed before, it has a special meaning the case when we are enabling event. It means to ignore whatever value of level assigned to events. In other words, just use the keywords specified for enabling the events. So it should just enable the two events, defined with the specified keywords. If we run this code, it shows the following output:



Level is the Max Level for Events
As we have discussed in the stairs diagram for Events. The event level assigned is the maximum value for the EventLevel considered for logging. In the following example, we are using EventLevel.Error for enabling the event. If we look at the diagram, we should realize, it would automatically include EventLevel.Critical and EventLevel.LogAlways. Let's change the configuration as follows:


As expected, it includes events assigned with levels as EventLevel.Error, EventLevel.Critical and EventLevel.LogAlways. Here is the output:



-matchAnyKeyword for Out-Proc Configuration
We can use a similar configuration for Out-Proc scenario. In the Semantic Logging service provided by Semantic Logging Application Block, matchAnyKeyword attribute is provided for source configuration. The value assigned to this keyword is treated differently. It is the sum of all keywords we want to enable. Here we want to enable Keyword.Creation and Keyword.AdmissionApproved. We need to just add the two numbers to calculate the value which should be assigned to the attribute. We can also use bit calculation by masking the two keyword bits. We can then convert the value in decimal as follows:



Let's use this in the configuration for the service. Here we are interested in the events with maximum level assigned as EventLevel.Informational. We are specially interested in the two keywords specified above.


Since we are using Windows Azure Sink with Storage Simulator, we should be able to see the following events logged in SLAB table.



Download

Semantic Logging Application Block In-Proc Usage

Semantic Logging Application Block provides various types of sinks. They include Console, File based, SQL Server and Windows Azure Table based sinks. We have been discussing how we can use these sinks out-proc. In this post we will be trying to focus how we can use these sinks in-proc i.e. in the same process where the ETW events are generated from. This is specially useful for scenarios where it is not feasible for running Semantic Logging Service as a separate process. I think the most common use would be desktop applications.

Let's create a sample console application SLABInProcApp targeting .net framework 4.5.



Since we would be using the sinks in process. We need to use the necessary nuget packages. As we know FlatFile, RollingFlatFile and Console sinks are directly available in EnterpriseLibrary.SemanticLogging package. The SQL Server and Windows Azure Table sinks are available in EnterpriseLibrary.SemanticLogging.Database and EnterpriseLibrary.SemanticLogging.WindowsAzure packages respectively. Since these packages have a dependency on EnterpriseLibrary.SemanticLogging package, installing these two packages should take care of all the necessary dependencies. These are the packages and their dependencies as shows in Package Visualizer.



And this is how the packages.config should look like for the project.

Now let us introduce our custom EventSource we have been using in these posts. As we have been seeing, it must inherit EventSource type available in System.Diagnostic.Tracing namespace. We can also introduce the necessary types for keywords, tasks. Here we have two logging methods with Event Ids set as 1 and 2.


IObservable<EventEntry> Implementation
SLAB provides ObservableEventListener. This is a specialized EventListener available (.net framework 4.5). As its name suggests, this is an observable type implementing IObservable<EventEntry>. Now SLAB provides various extension method to hook this observable type to the available sinks. In order to keep the world simple, for a given sink type X, the available extension is named as LogToX().



Here we seem to be interested in pushing the logs to Console, SQL Server and Windows Azure table. So we would be needing ConsoleSink, SqlDatabaseSink and WindowsAzureTableSink. These are provided through ConsoleLog, SqlDatabaseLog and WindowsAzureTableLog types respectively through their corresponding LogToX() methods. The extension methods for logging to SQL Server and Windows Azure Table are made available through installing their respective nuget packages.


There is some pre-requisites before we can push data to SqlServer and Windows Azure table here for this example. We need to create database (including the required objects). We also need to make sure that Storage Emulator is running on the machine running this application. This is only required for development. For the production application we can provide the necessary connection details. We have discussed the pre-requisites for SQL Server and Windows Azure table here.

And That's it! Ain't that simple!!!

Now we can just run the application. Since we have subscribed to the ConsoleSink through ConsoleLog.LogToConsole() extension method for IObservable<EventEntry> type, we should be seeing the following on the console.



Subscribing to WindowsAzureTableSink should push the following in the development table storage.



And finally we should be able to see the following data in Traces table in the SQL Server database used here:



Simplifying it Further
We can simplify the code even further. We don't need to instantiate ObservableEventListener ourselves. XLog types also provide the necessary CreateListener() methods. In addition to returning a new instance of ObservableEventListener, they also hook up the EventListener instance returned to the respective source sink.


Event Listeners and Application Life Cycles
Please note that this is a very simple example where you see these subscriptions and logging in the same methods. This would not be the same in the real-life application. You can consider this like Trace Listeners, they are added in the beginning of application life cycle. In the same way, EventListener subscriptions can also be done at the similar stage. They would be more suitable for application seams (Mark Seemann).

There are still some limitations about implementing interface type by the EventSource.

Subscribing Custom IObserver<EventEntry>
Since ObservableEventListener implements IObservable<EventEntry>, we can subscribe any IObserver<EventEntry> with this. Let's implement a sample IObserver<EventEntry> implementation.

We can use the CustomObserver to subscribe to the ObservableEventListener now. This should be using OnNext() method for any new event from the listener.


Download Code

EntLib Semantic Logging App Block - Event Text Formatting

In the discussion around Reactive Event Sourcing , we discussed briefly about text formatting for ETW messages. In this post, we are trying to understand the text formatting in a little more details discussing the different options available for text formatting for event data provided by EventSource as supported by Semantic Logging Application Block [SLAB].

In the examples for this post, we are going to be using Semantic Logging Service. We have discussed about it in the past. You can get yourself started with the installation and configuration of the service here: [Semantic Logging Service]

Sample Event Source
Let's create a sample console application EventSourceFormatting.csproj. We are adding the following EventSource to the project. It has only a single logging method which can be used when there is a request for password hashing.


Message Formatting
EventSource allows us to add a formatted message to the payload. Just look at the definition of RequestForPasswordHashing() method. Here we are decorating the event method with the Message property. You can notice that we are using it like string.Format() where we are expecting the arguments. The arguments are used from the Event method parameters with the same indexing. So for the example here, it would be using req for {0} and userName for {1}. The runtime would format the message using them and assign to event's Message.



The message and payload for the above event should be logged as follows:



Here we have called the event method as follows:


If you are using Semantic Logging Service to test this code with Sql LocalDB, you can use the following service configuration:


IEventTextFormatter
The message formatting as we described above, can format the message adding additional details from the payload. But we might need more than that. We might need to add some text in header and footer of the log being generated if we are using a file or console based sink.

SLAB supports text, JSON and XML based text formatting. The types are available in Microsoft.Practices.EnterpriseLibrary.SemanticLogging.Formatters namespace available in Microsoft.Practices.EnterpriseLibrary.SemanticLogging assembly. The assembly is downloaded using EnterpriseLibrary.SemanticLogging nuget package.



EventTextFormatter
EventTextFormatter is the simplest of all text formatters. It supports qualifying the event's data with additional details including header and footer. These are not the header and footer for the whole log file but each event data would be enveloped in them. Here We can add the following FlatFileSink to our service configuration. It has a simple EventTextFormatter with some specified header and footer details.


The Event Level specified on the sink is the minimum level. If there are error level events generated by one of the event source specified by the sink then they are also logged. You can notice how our event data is decorated with header and footer as specified in the above configuration using the EventTextFormatter by the FlatFileSink.


There is one more amazing option with EventTextFormatter which is missing in the other supported IEventTextFormatters (s). The option is called VerbosityThreshold. This is to further qualify the event for which we desire to apply this formatting. Let's first update our events as follows:


In the following example, we are interested in all the events from the specified EventSource which are at least set as [ Level = Informational]. But we want the additional verbose details only in the case of events with Informational level.


So all the events with level less than Informational wouldn't have the detailed verbose event detail. By default this is set as Error. That is why we were already seeing the detailed event data for Error level event. For our example, the data would be pushed to the sink as follows:


XmlEventTextFormatter
We can use XmlEventTextFormatter without any changes to the source application. Let's see below where we are updating the configuration of Semantic Logging Service. We are using the same Event source, still interested in the same event level. We are even logging to the same file but just in a different format i.e. Xml.


Here is how the same event data is logged in a different format. We don't have the header and footer data as we had for EventTextFormatter.


You can notice that message is still formatted in the same way.

JsonEventTextFormatter
Similar is the case for pushing the event data to the sink in JSON format. In the following Semantic Logging Service configuration, we have used JsonEventTextFormatter with FlatFileSink.

And now the same event data is pushed out to the file in JSON formatter. We don't even need to restart the source application for this change. Just look at the same data in a different format. This time this is JSON.


Why DataTimeFormat Property?
In our EventSourceAnalyzer discussion we mentioned that DateTime data type is not supported for event payload. If you look at the definition of IEventTextFormatter, it has a DateTimeFormatter property. Why in the world do you need to format this when it is not even supported. Just Don't get too excited!!!

The DateTimeFormat is not for the payload data. It is for the event data. If you look at the log file, you can find that all the events are logged with TimeStamp. This formatting is to applied for that Timestamp. Let's update the service configuration as follows:


Just notice the TimeStamp format. You can compare this with the TimeStamp format before.


Source Sinks & Supporting EventTextFormatters
It must be remembered that all sinks don't support every text formatter. There are only a few which support these formatters. In the following image, I have tried to list sinks and the supporting Event Text formatters.



Source Sinks support a maximum of a single text formatter. It can be any of the supported text formatter as presented above.

Changing the Semantic Logging Service Configuration
It must be remembered that we don't need to restart the service after every changes in the service configuration including additional / removal of an event sink. Here we are running the service as a console application. Just look at the detailed message when we changed the configuration. Isn't that great? Zindabad!!!



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

SLAB - Reactive Event Sourcing

In the previous post we saw how we can use ETW events generated using EventSource using PerfView. We can also use these events in our application using EventListener. This is another new abstract type provided in .net framework 4.5. The abstract member is OnEventWritten() method. Additionally, it has a virtual method OnEventSourceCreated(). Below is a custom event listener. Here we are overriding the two members. We are just writing the debug messages when these methods are called. During development, debug messages can be seen in the Visual Studio's Debug Output window.


The listener's OnEventWritten method is called when EventSource writes an event. But before that we need to specify what level of events we are interested in from the EventSource. This is called Enabling the events where listener is specified with the EventSource and EventLevel.

You can notice OnEventSourceCreated and OnEventWritten being used by the logs in the Output window. The above code wold result the following logs:



Semantic Logging Application Block
Semantic Logging Application Block is provided in Enterprise Library 6 for supporting structured logging. It enhances EventSource to support logging events in SQL Server and Azure tables. Like other application blocks, this is also available as a Nuget package.



SLAB provides custom implementation of EventListener. The listener is Rx's IObservable. This is named as ObservableEventListener. Since this implements IObservable, it allows subscriptions from Event sinks. The sinks are IObserver (s) to observe on these event listeners.



The application block also provides a specialization of EventSource. This is named as SemanticLoggingEventSource.



In-Process Vs Out-Process
SLAB can be used in-process or out-process. We can use the Nuget package to use the libraries for using it in process. For out of process, it is hosted as a windows service. The service installer is available as a separate download. In the previous post, we discussed how we can use out-process logging with SLAB.

Event Text Formatter
SLAB supports JSON and XML based text formatting. The types are available in Microsoft.Practices.EnterpriseLibrary.SemanticLogging.Formatters namespace available in Microsoft.Practices.EnterpriseLibrary.SemanticLogging assembly. The assembly is downloaded using EnterpriseLibrary.SemanticLogging nuget package.



Event Sinks & Factories
SLAB also provides Event Sinks and their factories. All of these event sinks are IObserver.



Let's install EnterpriseLibrary.SemanticLogging application block nuget package. The package should take care of all its dependencies installation as well, which is only comprised of Newtonsoft.Json package.



Let's also install Rx-Main nuget package for subscriptions using Reactive extensions based subscribers.



In the following code we are subscribing to ObservableEventListener. We can get the messages in the OnNext() method for the subscriber. Here we have also used OnCompleted() and OnError() of the subscriber.

Running the above code would result in the following output. Please notice that the messages being logged using the event source as provided to the listener. Since we are subscribing to the listener, we are getting those messages in OnNext(). Here we are just writing those messages to Debug Window.


Download

Semantic Out-Process Logging using Semantic Logging Application Block - File Sink

In this post, we are going to look how SLAB (Semantic Logging Application Block) can be used for out-process logging for ETW events. Pattern & Practices (P&P) team has provided support for out-process logging of ETW based logs using Semantic Log Service. The executable for the service can be downloaded from here: [ http://go.microsoft.com/fwlink/p/?LinkID=290903 ]. Let's copy the downloaded installer to the some folder.



Running the executable extracts the required files in the specified directory. Here we are specially interested in install-packages.ps, the power shell script to download the required nuget packages to the directory.



Let's run the power shell script. This would download the required nuget packages as follows:



It must be remembered that the Semantic Logging Service must run on the same machine as the source application emanating ETW events data. We need to update the configuration of the out-proc service to utilize the events. You can see that we have updated the event source definition to look for the specified events. Here we have used FlatFileSink. This would write the events data to the file specified. In the current example we are using SemanticETWLogs.log, which would be created in the same folder. Here we have also used the text formatter which would create header text. In the next post, we will be introducing what other text formatting options are available.


Now we can run the out-proc process to register and log the ETW events. The process can run as a Windows Service or Console application. For our example, let us run it as a console application. This requires -console switch to be used to run it. Please make sure that you are running this with a command prompt using the Administrative privileges, otherwise, the command results in a failure.



Now we simply need to run the source application. Since it is registering some events, the logs are available in the specified file. For my case the data is as follows:


Please make sure that your EventSource is decorated with the attribute to specify the ETW event expected by out-proc listener.


Download