8. Event Log

When the first version of the framework was released I had high hopes for the EventLog class. At that time I had a lot of experience using the NT Event Log and although I had a lot of respect for the service, I recognised that the API for logging to and reading from the event log was somewhat arcane. I had written several class libraries of my own, and I even published one, but I recognised that these still required the user to write a resource only DLL (more about this later) and that there must be a better way. During this pre-.NET time, I even had a look at the unmanaged Visual Basic object to log messages to the Event Log, however, this confirmed to me that I was better off using C++ because the Visual Basic guys had to use an appallingly bad mechanism to log messages to the Event Log.

8.1 The Event Log Architecture

To understand how best to use the event log you have to understand how the event log works, which means that you need to know about the unmanaged API. So bear with me during this section, learning these basics will help you to use the event log more effectively.

The first thing to mention is that when you report an event you do so through an event log source. As the name suggests, an event log source is a process that provides events. An event log source is associated with just one event log and, because of the way that the messages are stored, an event log source has associated resource files. An event log source has to have information in the system registry, to indicate the event log where the events will be placed, and the location of the resource DLLs that will be used.

By default, the system will have three event logs: Security, System and Application, but you can create your own. You cannot log to the Security log because it is used for auditing messages and the System log contains messages from device drivers, so in general, you should log your messages to the Application log. Even though you can create your own log, it is best to use the Application log. The reason is that it is often important to see how the messages from your application relate to message from other applications and so collating all the messages in one event log makes this possible.

However, this does put a great responsibility on application developers that they only log relevant messages, so that they don't swamp the Application log. It is for this reason, that some errant applications act in an irresponsible way and log trivial messages, that some people recommend that applications should have their own event logs. My solution is to make developers aware about what they should and should not log so that they behave responsibly and create applications that coexist with the other applications on the machine.

If someone suggests to you that an application should have its own event log then you should question the logging policy of the application because it means that they are admitting that the application is producing too many trivial message that should be disabled in production builds, or should be sent to some other logging mechanism.

Before unmanaged code can add a message to the event log it must first open the log. Here is where things get confusing. To write to the event log you have to open the event log with the unmanaged function RegisterEventSource which returns a handle. When you have finished using the event log you must release this handle by calling DeregisterEventSource. Let me be absolutely clear here, when you call RegisterEventSource you are not registering an event source. Event sources do need registry entries, but you do not create these entries with this function. This function opens the event log that the specified event source is registered to use. The actual event log is a file on disk that is used by one or more event sources and access to this file is controlled by the event log service. The RegisterEventSource  method associates the event source name with the handle returned for the log, so that when the application logs an event, the event log service can write to the correct file, and add the name of the source to the record it writes. A better name for the function to give write access to the event log would have been OpenEventLogForWriting. There is also a method called OpenEventLog, but the handle returned from this method can only be used to read the event log and when you are finished with the handle it must be released with a call to CloseEventLog. It would have been better if OpenEventLog had been called OpenEventLogForReading to make absolutely sure what the handle is used for. Finally, note that the handle created for reading must be closed with CloseEventLog and the handle created for writing must be closed with DeregisterEventSource: you cannot use CloseHandle, which complicates matters unnecessarily.

To add a message to the event log you call the ReportEvent function. The function looks like this:

hEventLog is a handle to the event log with a call to RegisterEventSource. The function writes the message to the event log that is associated with the event source associated with the handle; this method does not have a parameter for the event source name because the source name has already been associated with the handle. wType indicates how severe the message is (information, warning, error) and wCategory is an additional level of categorisation that is defined by the application. lpUserSid is a system security ID that you can use to identify the user that was logged on when the event was reported.

The interesting parameters are dwEventID, wNumStrings and lpStrings. dwEventID indicates which event you are reporting, and is a criteria that you can use when filtering events using the event log viewer, but more importantly it identifies the number of a resource string in a resource-only DLL. This string is a format string with placeholders for parameters that you will supply when reporting the event. lpStrings is an array of strings and the number of strings is given by wNumStrings. These strings correspond to the placeholders in the format string. The user can also log a binary value (passed through lpRawData and the size is given in dwDataSize) but you are encouraged to keep the amount of data small.

The use of the word strings is important. The placeholders can only contain strings. I will explain in detail later, but as you read the rest of this description it should become apparent to you.

All of this information is stored in the event log in the form given in the function, that is, the event log has the type, the category ID, the event ID and an array of strings. and (if present) the binary data.

A process calls ReadEventLog to read entries from the Event Log:

The hEventLog parameter is a handle returned from a call to OpenEventLog. This function will read as many records as it can starting from the record with the index dwRecordOffset. The method does not indicate how many records should be read, it just indicates how big the buffer is and allows the function to read as many records as it can. The user allocates the buffer pointed to by lpBuffer and provides the size of this buffer through nNumberOfBytesToRead. If this buffer is too small the function will return an error and provide the minimum size of the buffer through pnMinNumberOfBytesNeeded. The data that is returned will be zero or more EVENTLOGRECORD structures.

The seven fields at the end are interesting, and I will return to them later. This structure contains the information that was passed to ReportEvent: the event ID (EventID), the number of strings (NumStrings), the event category (EventCategory) and type (EventType). It also contains information added by the event log service when it added the entry to the event log: the time that the event was submitted (TimeGenerated) and the time it was actually written to the log (TimeWritten, indicating that the event log service uses a queuing system), a record identifier (RecordNumber that can be used for the dwRecordOffset). The EVENTLOGRECORD has a fixed size, but it also has a Length member. This is because every structure is followed by a variable amount of data (the seven commented 'members'). The size, and the offset (from the beginning of the structure) of each of these items is given by fields in the structure. So StringOffset gives the location of the start of the string buffer, each one is NUL terminated and the number of these strings is given by NumStrings. If an application specified binary data when reporting the event then this data will be in a buffer at the offset DataOffset from the beginning of the structure. The event log service will provide the name of the event log source (ie the application that generated the event), which identifies a registry key that has a value that contains the name and path to the resource DLL. This DLL has the format string identified by EventID used to generate the complete, localised, event message.

Note that one of the variable length strings is the computer where the event log source was running. The interesting point about this last statement is that you can call ReportEvent on one machine to add an event to the event log on another machine. This is possible because RegisterEventSource takes the name of the machine where the event will be logged as well as the name of the event source. This supposes that the account calling ReportEvent has the permission (the ELF_LOGFILE_WRITE access right) on the remote machine. It also assumes that the format resource-only DLLs are registered on the remote machine. This is one area (amongst others) where the .NET EventLog class fails hopelessly, so badly that I do not think that the designers even knew that it was possible to write events on other machines.

Notice that the event log does not contain a complete, formatted string. It contains identifiers that indicate how to obtain the format string (EventID and SourceName) and the strings that should be used to replace the placeholders in the format string. A process that displays event messages will read this registry value, load the DLL and pass the DLL handle, the event ID and the format strings to FormatMessage which will return the formatted message.

Notice the parameter dwLanguageId. This is a language identifier (or if you supply zero then the function will deduce a language ID from the thread, user or system default language ID). This is an important parameter because the locale is obtained from the caller of FormatMessage, which will be the process that will display the message. The local of the process reporting the event is not relevant, and neither should it be. The process reporting the event is decoupled from the localisation of the message. This is something that was completely lost on the designers of the .NET EventLog class, the documentation for this class for 1.1 and 1.0 indicated that the application reporting the event should localise the string, which is a presumptious thing to do.

This function can be used in many ways, and the dwFlags parameter is used toindicate how the formatting should occur and who has the responsibility of allocating the buffer for the formatted string. You can call this function and pass it a format string, but the usual way with the event log is to indicate that a resource file is used, and in this case lpSource is a handle to a DLL that has been opened with LoadLibrary. dwMessageId is the resource identifier for the format string in the DLL and is the same as the event ID.

Creating a resource file for the format strings is easy, but I will leave that for another section because (finally!) the ability to use resource DLLs has been added to the .NET EventLog class in .NET 3.0/2.0. (But don't get too excited about this, the class still allows you to abuse the event log.)

Overall, reporting and reading events looks complicated, but it is actually quite an elegant solution. The first point to make is that by using a format string with placeholders and insert strings you can minimize the size of the event log records and the corresponding event log files. In these days of huge hard disks this might not seem to be important, however, if you have sufficient privileges you can access the event log on another machine, and minimizing the amount of data passed over the network is still an important issue. The other point to make is that the responsibility of formatting the final message is the responsibility of the reader of the message and not the writer. The reader could be in a different country to the writer (remember, you can read the event log of another machine) and might not speak the same language, but this is not a problem because the reader just needs to have the format strings localized to her locale.

Think how elegant this is: the writer of an event log message does not have to know the locale of the reader, readers in two different locales can read the same event log information localized to their own languages.

As I have mentioned, the mechanism of creating a resource-only DLL with the format strings is straightforward and registering this DLL with a source name is also straightforward. However, in Microsoft's opinion it appeared to be beyond the capabilities of Visual Basic programmers (perhaps there was some truth in that). The EventLog object in unmanaged Visual Basic registered the same resource DLL for all event sources and every format string in this DLL wss of the form:

That is, the format string has no static text and it contains just one placeholder. This meant that the VB code had to format the entire message and pass it to the event log. That meant that the event log contained the entire message which bloated the event log and had the serious downside that the Visual Basic developer had to decide what language the reader will use. Microsoft do not provide a crystal ball in the package that contains Visual Basic, so the developer had to guess. Not a particularly good situation.

If that was bad, now look at what has happened to categories. The category is specified by the developer through the category ID passed to ReportEvent. This category ID is specific to the event source because it should be something that is meaningful to the application. To do this, the category ID is the resource ID of a string in a resource-only category resource DLL (often the same DLL as the format strings). Since Visual Basic specified that every event source has the same format DLL and the same values in the registry, there was no way that a Visual Basic developer could provide the name of a category. If a program like the system event log viewer (eventvwr) cannot find the string for a category it just gives the category number.

All of this meant that unmanaged Visual Basic screwed up the data that the event viewer shows, bloated the event log, and raised the possibility that events could be written over and hence causing a data loss. Could life get worse than this? It did, guess what, the .NET EventLog class in 1.1 and 1.0 (and, unless you take steps otherwise, in 3.0/2.0) has the same problem.

Now you can see why I had such high hopes for the .NET EventLog class, I had seen that the Visual Basic team were clearly incapable of producing a suitable solution and that their solution was causing damage. I had hoped that the clever people behind the .NET framework library would come up with a great solution. Unfortunately, I forgot that some of the people on the .NET framework team were drawn from the unmanaged Visual Basic team. The EventLog class in System.Diagnostics in .NET 1.0 worked exactly the same way as the EventLog class in unmanaged Visual Basic. In fact, I wouldn't be surprised if Microsoft had merely ported the implementation of this code to .NET, it is that bad. Microsoft rather weakly says that you should localize the messages for the reader, but does not indicate how you can determine what locale the reader is in.

Let me re-iterate this: prior to .NET 3.0/2.0 the EventLog class was worst than useless for reporting event log messages and I frequently advised people to refrain from using this class until Microsoft had fixed it. At the same time I took every opportunity to point out to Microsoft that what they had provided was wrong. However, Microsoft does not like criticism from me (however constructive) and chose to ignore my protestations and leave this horrible class in the library. Unmanaged Visual Basic lives on in the .NET framework library.

The version of EventLog in .NET 3.0/2.0 is a minor improvement over the version in 1.0 and 1.1 because it allows you to log messages using events defined in your own resource DLL (WriteEvent). However, although Microsoft allow you to use a resource-only DLL they do not provide the tools in the .NET SDK to actually allow you to create one. So their changes in .NET 3.0/2.0 is at best half-hearted, and at worst it shows their contempt for developers who want to do the right thing.

Since the EventLog class still contains the feculent method WriteEntry and makes no attempt to mark it as deprecated, and since the .NET SDK does not contain the message compiler, I still regard this class as broken.

8.2 What Is The Event Log For?

Before you can do anything with the event log you have to obtain an understanding about what it is for and how you should use it. This will help you understand inappropriate and inconsiderate uses of the event log and learn how to use it properly. It is difficult to answer this question in a few pithy words, but here's a good try:

The event log is a semi-permanent central storage of messages from applications, particularly those without a user interface.

The first important point is that it is a central repository and hence it is shared by many applications. Even the most pared down copy of Windows will have several services and none of these will have a user interface. (You never see a service's window, you only ever see an application that talks to the service). Since services do not have a user interface the only way that they can give the user any indication about how it is working is through a separate process. Furthermore, a service can run when there is no interactive user (indeed, this is one of the main reasons for implementing a service, because you can schedule a service to start whenever the machine starts) so any messages intended for the user must be stored so that when the user logs on it can access those messages.

Since there are many services on a machine, it means that several services must share the same repository so that the user has just one place to look for the messages. Further, many services are interconnected, that is, they use the facilities of other services. If one service fails then the services that depend on it may fail too. If you get an error message from ServiceA saying that it has failed, you will direct your attention to ServiceA. However, if you get two error messages, one from ServiceB followed by another from ServiceA and you know that ServiceA depends on ServiceB then you can deduce that the error from ServiceA was caused by the error from ServiceB which should now get your attention. If you did not know about the relationship between the two services then you would not be able to make this deduction, but more importantly, if you did not see the two related messages in the order they were generated then you would not be able to make the deduction either. Thus, it is vital that you can see the details: see the trees from the woods to turn around the saying. So that individual messages maintain their significance a service writing to the event log must keep the number of events it generates to a minimum, and only log important messages. Trivial messages will merely act as a mechanism to hide the important ones.

The event log is a semi-permanent storage of messages. By semi-permanent I mean that the user can clear the event log and that the event log service can clear a log too. Using disk storage means that you have a history of generated messages. However, it does suppose that there is enough disk space to contain all the messages. Although huge hard disks are ubiquitous these days, they were rarely seen when the event log service was first written. Even if a machine does have a huge hard disk often it will be partitioned and the system partition (containing the Windows folder) will be deliberately kept small.

To help with this, the event log can be configured to restrict the size of the disk file used by a log. Here's the properties of the Application log on my machine (accessed through the eventvwr tool).

Notice that the log file is restricted to half a megabyte, if the file grows larger than that it is set to overwrite messages, but only if they are older than 7 days. From a quick scan of this log I can see that the oldest message was five months ago, which gives me a fair amount of 'history' to use when I am troubleshooting.

From the last section you know that the basic size of EVENTLOGRECORD is 56 bytes, however, the majority of the record will be taken up by the optional members. From my machine (and completely non-representative) I measure that the average size of a record in the Application log is 282 bytes, in the Security log is 248 bytes and in the System log is 140 bytes. Assuming that applications continue to log messages of a similar size I can assume that the Application log can take 1800 messages. In the five months since I last emptied the event log on my machine, the Application log has accumulated 1100 messages so I have a while to go before the older messages get overwritten. However, an errant application, generating lots of messages, could fill up the event log in a matter of minutes and hence remove the important historical aspect of the event log.

8.3 The Event Log Viewer

The Event  Log Viewer is a system supplied snap-in for MMC, you start it from either the Administrative Tools Control Panel folder, or you can start it from the command line by typing eventvwr. This will list the available event logs in the left hand tree view and the messages in the log in the right hand list view. The messages are typically sorted according to the time that they were generated, this is the most useful because you can see how messages relate to each other. However, you can sort by any of the other columns.

If you double click on an entry you will get the complete message including the formatted message:

Notice that there are two arrow buttons, this means that you can use this dialog to browse through the messages. The third button will copy the message to the clipboard, for example:

 

Close down this dialog. You can also provide a filter for items in the list view. This is particularly useful when you have many hundreds of messages from an errant application. To do this select Filter from the View menu.

The Event source pull down list is interesting because it will list all the event log sources registered on your machine. In addition to the source you can filter on the event ID, category, the user and computer, and you can specify that only messages between two specified times will be shown. Close this dialog without setting a filter (Cancel). Select the top level Event Viewer in the left hand tree view. The list view should now contain all the logs. Right click on one and select properties. This should show you the property dialog shown earlier:

Through this dialog you can determine the size of the log and the policy for overwriting events.

Close the dialog and right click again on one of the logs, notice the three menu items: Open Log File, Save Log File As, Clear All Events. As the name suggests, Clear All Events will remove all events from the log file, if you do this you will be asked if you want to save the events first, either as a text file, a comma separated value file, or as the native evt format. If you save the file in evt format then you can copy it to another machine and use the Open Log File item to load it and assuming that the other machine has the event sources registered you'll be able to read the messages formatted for the locale of that other machine. The final context menu item of interest is New Log View. As the name suggests it will create a view of the selected log. Thus you can view the same event messages with two different filters applied.

Finally, right click on Event Viewer in the left hand tree view and select Connect to another computer. This dialog allows you to specify the machine that you want to use, this can either be the local machine or another machine. The console will only show the logs from one machine. Bear in mind that logs can be large and so if you read the events from a remote machine it might take some time to display the data in the event viewer. If you view a message from an event source that is registered on the remote machine, but not on the local machine, the event viewer will warn you. Here's a typical message:

This indicates that the remote machine has the Bluetooth service installed but the local machine does not. The remote machine has an entry indicating that the service started. You will want to make sure that messages like this do not appear from your applications. This means that you should provide message resource files, and you should take steps to ensure that your event source is registered on every machine that will read your event log messages. Note that this is the case even if you use the feculent WriteEntry method, so if you have to register an event source, you might as well do it correctly.

At this point, if you have opened a log on a remote machine, right click on Event Viewer in the left hand tree view and select Connect to another computer and then select the Local computer option, click OK and close down the tool.

8.4 Reading The Event Log

I will split up the discussion about the EventLog class into two: reading and writing. In general, this class is adequate at reading the event log and it makes reading events simple. However, this class is completely inadequate at writing events.

The first thing you have to do is to indicate the machine that you want to read. Usually you will want to read from the local machine, but you can read from a remote machine if your account has the appropriate access. However, regardless of the way that the Microsoft's .NET designers want you to access the event log, you cannot get away from the fact that the message that you will receive will need to have to be formatted using FormatMessage which means that the appropriate format DLL will have to be available locally. Thus, if you read messages from another machine for an event source that is not registered on your machine, you will not be able to get the complete formatted message. Microsoft's opinion is that this does not matter for messages created with the feculent method WriteEntry because no formatting is required by the reader, however, event though the message will be readable, the user will get a message from the event log viewer saying that source cannot be found. This is extra information that may confuse the user, and confusing the user is something that you should endeavour to avoid doing. Furthermore, most messages in an event log will be generated by applications that use proper event logging and hence will require a format DLL. If you do not give a machine, then the local machine will be used.

Next, you have to indicate the log that you will read. This will usually be one of: Security, System or Application. The EventLog class provides the static GetEventLogs method that will search the local (or remote machine) and create an array of EventLog objects, one for each of the logs on the machine. You can also pass the name of the log to the EventLog constructor to get access to the specified log. Once you have an EventLog object you can access the Entries property to get access to the event log messages through EventLogEntry objects, here is the public interface (edited):

Most of these are self-explanatory. Message is the formatted message for the event, it is the format string with the ReplacementStrings inserted in the placeholders. Index is the record number in the event log. InstanceId is essentially the index of the resource string ID but note that EventLogEntry also has an EventId member. The difference is that InstanceId is the lower 30 bits of EventId, the top two bits were added to the resource ID by the message compiler to indicate the severity of the messages as explained later, but they are usually both zero, so EventId and InstanceId are usually the same.

Let's take a look at how this works. Since your event log will most likely contain lots of events you will develop a Windows Forms application with a ListView control to display them all. Create a file (read.cs) and add this code:

using System; using System.Windows.Forms; using System.Diagnostics; class App : Form {    TextBox txtMsg;    static void Main(string[] args)    {       string log = "Application";       if (args.Length != 0) log = args[0];       Application.Run(new App(log));    }    App(string log)    {       this.WindowState = FormWindowState.Maximized;       Label lblStatus = new Label();       ListView lvMessages = new ListView();       txtMsg = new TextBox();       lvMessages.Dock = DockStyle.Fill;       lvMessages.View = View.Details;       lvMessages.FullRowSelect = true;       lvMessages.ItemSelectionChanged += Clicked;       this.Controls.Add(lvMessages);       lblStatus.Dock = DockStyle.Top;       this.Controls.Add(lblStatus);       txtMsg.Dock = DockStyle.Bottom;       txtMsg.Multiline = true;       txtMsg.Height = 150;       txtMsg.ScrollBars = ScrollBars.Both;       this.Controls.Add(txtMsg);       lvMessages.Columns.Add("Source", 100);       lvMessages.Columns.Add("Message", 1000);

This just sets up the infrastructure of the form. The application is intended to be run with a command line parameter that is the name of the log that you want to view (or if you do not give a parameter then the Application log will be used). The window is created maximised with a static control at the top and a text box at the bottom and in the middle there is a multi-column ListView control. When the ListView is clicked the Clicked handler is called.

The remainder of the constructor looks like this:

Note that the EventLog object will hold on to a system handle so the object should be disposed as soon as possible which is why I have used a using block.

As I mentioned earlier, the event log is designed to localise everything and even the name of the event log is localised. For a correctly installed event log (sadly few custom event logs are correctly installed) the registry entry for the event log will provide a resource file which contains one or more localised names for the log. The LogDisplayName property returns the localised name. If the log does not support localisation then the name of the registry key will be returned, this is the value returned from the Log property.

Is it any surprise to you that if you create a n event log with EventLog there will be no registration information about the localised name of the log? If you choose to do the right thing you will have to write your own code to do this.

The two columns in the ListView are filled with the name of the source and the formatted message.

Finally, add the Clicked handler:

This puts the source and message in the text box so that you can read it easier. Compile this code as a windows application (csc /t:winexe read.cs) and then run it without a command line. You'll see that the list view will fill with items. Click on a row and look at the value in the text box. Try several items. You should see that some of the messages contain newlines, in other words, formatted to be viewed in a text box.

Close it down and restart it with System and then Security as the parameter to convince yourself that you can read all the standard logs. When you do this pay attention to the range of messages that the logs contain and the different event sources that log messages.

8.5 Event Log Messages

On my machine I have installed Visual Studio 2005, .NET 3.0 and the beta VS extensions for .NET 3.0 (Orcas). Here are some of the messages. Note that they are contiguous with no messages from other applications (so these messages are generated solely by the installation program and not caused by any other service):

Source	Messages
.NET Runtime Optimization Service	42 Information messages: 21 saying that it had started jitting an assembly; 21 saying that it had succeeded the jitting.
.NET Runtime Optimization Service	46 messages: 23 Information messages saying jitting had started; 23 Error messages saying that jitting had failed, with an error code but no real indication about why the JIT had failed
.NET Runtime Optimization Service	14 Information messages: two pairs of 7 saying jitting had started and that jitting had completed
.NET Runtime Optimization Service	1 Information message from ngen saying that it had finished work
MsiInstaller	35 Information messages about installation of the Windows SDK, each message said which component it had installed
.NET Runtime Optimization Service	46 messages: 23 Information messages saying jitting had started; 23 Error messages saying that jitting had failed, with an error code but no real indication about why the JIT had failed. This was clearly a repeat of the previous jit operation.
Visual Studio - VsTemplate	56 warning messages from installing Orcas (the .NET 3.0 extensions for VS 2005) saying that there was an unknown element error in the script (caused by the installation of Orcas for WCF and WPF)
Visual Studio - VsTemplate	56 warning messages from installing Orcas (the .NET 3.0 extensions for VS 2005) saying that there was an unknown element error in the script (caused by the installation of Orcas for WF)

What do we learn from this? Well, from almost 300 messages (more than a quarter of the messages in the log) I deduce that the installation was not 100% successful. That is all!

Let's take these items line by line. When the .NET framework is first installed each framework assembly is JIT compiled to produce a native image. The native image is not distributed with the installer because the JIT compiler will work differently on one machine to another depending on the machine's configuration. The first 42 messages say that 21 assemblies have been successfully JIT compiled. However, having two messages is a waste. The only person interested in whether the JIT started is the person who develops the JIT compiler, it is of no use to me. Furthermore 21 messages saying that 21 assemblies have been JIT compiled is no use to me either. A single message saying that 21 assemblies have been compiled is interesting, but it does not help me when tuning my machine or looking for problems. Similarly the next 46 are pretty useless to me (as the owner of the machine): I have 23 useless messages saying that JIT compilation has started and 23 messages saying that the compilation failed but little information why. Here's one such error message:

The error is FACILITY_WIN32, so 0x8007002 is ERROR_FILE_NOT_FOUND. I know this because I could be bothered to look up the error code, the person who generated the error could not be bothered to do this. I assume that the file that could not be found is Microsoft.ReportingServices.QueryDesigners.dll but this is not specified. Neither is the folder that was checked. As I said, this information is useless to me because there is no indication how I can fix the problem. It would have been far better to have just one message saying that there were 23 errors and then point me to a separate file containing the errors.

Similarly, the 35 information messages from the MSI installer are pretty pointless, it would have been better to put this in a file. Finally, the 56 warning messages should also have been put in a file and a single warning message indicating that some of the installation had failed. Since this was a beta product these warning messages would only be important to the developer of the product, but for me, they give no useful information. The initial install of the .NET framework and Visual Studio should at most have given just one message each (".NET framework installed and assemblies are JIT compiled" and "Visual Studio 2005 installed"). I can accept the JIT compiler service indicating that it has created a native assembly, but not when there are 50 assemblies and definitely not two message per assembly. Again, when an MSI package is installed I can accept an information message, but the Windows SDK is just one "application" (look at how many entries cover it in the Control Panel Add/Remove programs applet) and so there should be just one message indicating that either the installation succeeded or failed; 35 messages is excessive.

Finally, when some action fails, then it should fail. The behaviour of the Orcas extensions for VS2005 is a great example of what happens if an operation that fails, but it is allowed to continue without addressing the fault. There is clearly some incompatibility issue, for example:

Each of the 56 messages from Visual Studio - VsTemplate complains about MinFrameworkVersion, so surely one message would have been sufficient?

Here's another example. I once worked on a system that had a TCP based library. If the library could not get a connection it generated an error, then it would wait a short amount of time and try again. One server on a client site was having problems and we asked for the event log file. The entire file was filled with the error message from the TCP library. It turned out that the ethernet cable had a loose wire which sometimes would put the machine offline for several hours, a problem that was easy to fix, but since the repeated messages had overwritten all the other event log messages we were unable to determine if there were any other problems with the machine. The moral of this story is clear: restrict the number of messages that you write to the event log, and if you need to provide detailed information put this in a separate file on the hard disk.

Unfortunately, the .NET framework encourages you to fill the event log with trivial messages. They do this by providing a trace listener class for the event log (EventLogTraceListener). The whole point of trace messages is that they are chatty and provide detailed information, so the worst place to put those messages is in the event log. Yet again, this is the work of a Microsoft developer who clearly knows nothing about the event log.

Before moving on to how to write events it is worth pointing out that the EventLog class can be used to monitor a log for new events, that is, to indicate that when a new event has been written your .NET class should be notified through a delegate. You can be informed about events from any source. To use this, you need to open an event log, then add a delegate to the EventWritten event. When you want to allow events to be received set EnableRaisingEvents to true. This calls the Win32 function NotifyChangeEventLog that sets up the infrastructure to call the delegates in the class's event. When you no longer want to be notified of event messages set EnableRaisingEvents to false. The event handler is of the type EntryWrittenEventHandler, which has an argument parameter of type EntryWrittenEventArgs which has a single property called Entry which is an EventLogEntry object.

8.6 How Microsoft Wants You To Write To The Event Log

Before you post to an event log you should create an event log source. As I mentioned earlier the Win32 RegisterEventSource associates the event source name with a handle used to write messages, but in addition an event source name must have a registry entry. The registry entry should only be created once on a machine, but note that as a considerate developer you have to ensure that when the application is uninstalled the registry entry is removed. The registry entry for an event log source is more 'contained' than the entries for performance counters, in that you add the information for your event source to a key for the event source and only used by that event source (although, as you'll see, additional information is written on your behalf) so removing the registry information involves removing just that key. The EventLog class provides the static CreateEventSource method to add the registry information and the static DeleteEventSource to remove it. CreateEventSource has three overloads: one is obsolete, so I'll ignore it; and I will cover another in the next section. The remaining overload takes two strings: the name of the source and the name of the log where the source's events will be logged. There are two overloads to the DeleteEventSource method, both take the name of the source.

Create a file (writer.cs) and add the following:

This uses the same mechanism that I used in the performance counter example, that is, if you run it without a parameter the code checks to see if the source exists and if not it creates the source and exits. If the application is run with a parameter (it does not matter what) the application removes the source and the log (warning: see note below before you alter this code).

Make sure that your code is exactly the same as the code above. Compile it, then run it without a parameter, you should get a message saying that the event source has been created. The code is written to ensure that the application ends after creating the source because, as you'll see in a moment, the event log service needs to act upon this information.

Start the registry editor (regedit) and navigate to the following key:

Under this you'll find a key with the same name as the source you created (Acme_Source).

As you can see, the only entry in this key is the name of the EventMessageFile. I will return to this in a moment, but first take a look at the Application key (under the EventLog key). Here you'll find the values for the location of the file, and its maximum size, the retention policy and values to handle localisation of the log's display name. In addition you'll find a multi-string entry called Sources. Double click on this value, but whatever you do, do not change the contents of this value. Scroll through the value, you'll see that it contains the names of all the sources in this log, including the one you just created. The CreateEventSource method only created the TestLog key, the Acme_Source key and the values in it. However, the event log service monitors the keys beneath the EventLog key and when a new key is created it adds the key name to the list of sources. This is why you should close down the application after creating a new event source, this allows the event log service time to update it's registry values.

I once wrote a C++ class library for NT4 that simplified the registration of event sources. For reasons irrelevant here, the class library copied the entire EventLog key, inserted the new key and then wrote the key back again. The first time I ran this code it killed the event log service and after it restarted the service started to show odd behaviour. It would log messages to the wrong log and when I read messages it would get the logs mixed up. No amount of manually editing of the registry would get me back to a situation where the event log service worked correctly. The only solution (since system restore was not available then) was to reinstall NT4. I do not know if this is a peculiarity of NT4 because I do not want to try it out on my current development machines. What I did learn was that I should not mess with the event log registry values that I did not know about.

Now navigate to the TestLog key (the key fro the custom log you created). This was created by the CreateEventSource method. Compare the number of values with the number of values under the Application key. The most obvious difference is that the TestLog key does not have localisation values (DisplayNameFile, DisplayNameID), but there are two others: PrimaryModule and RestrictGuestAccess.

Review the code to delete the event source:

In this example logName refers to a custom log you created (TestLog) but in most cases (assuming you use the event log correctly) you'll want to use the Application log so that you can see how your event messages are related to event messages from other applications. Can you see the problem with this code? If you change logName to have a value of Application (do not do this!) then when you perform the clean up code the Application log will be deleted! How braindead is that code? At the absolute minimum the Delete method should check to see if the requested log is one of the system logs and throw an exception. There will never be a reason for you to need to delete any of the system logs. "Ah," you say, "but if I delete the Application log I can always re-create it with CreateEventSource". Yes, that is true, but bear the following in mind: first, you will have deleted the event log file, so all the events for all applications on your system will have gone to the great bit bucket in the sky and you will not have made a backup copy (refer to what I say below about Clear); second, between the time that you deleted the event log and re-created it, applications on your machine will not have been able to log events - not a good thing; third, you will have deleted all the entries for all the other application event sources on your machine with no simple way of getting those values back, which may well result in those applications being unable to report any more events; and finally, as mentioned above, the EventLog code to create event log keys omits four keys. Deleting the Application log/key is a bad, bad thing to do!

WARNING: do not use EventLog.Delete without first checking the name of the log that will be deleted. If you blithely delete one of the system logs you will have deleted a system resource, a resource shared by all processes on the machine.

To fix this problem I need to check that the log being deleted is not a system log. I first thought about checking the registry key with the name of the log file to see if it has one of the four values that EventLog does not create and using the absence of these keys as an indication that the key is associated with a custom log, but then I thought that there would be a very small chance that Microsoft might decide to fix this class, or (the more likely case) that you might decide to fix it. This would mean that my checks will prevent you from legitimately deleting your own custom logs. So the simplest way to fix this code is simply to check to see if the requested log name is one of the system logs.

Add the following using statement:

Now change the Main method:

The static method LogNameFromSourceName can be used to determine which log contains particular source, and I use it here to make sure that the correct log is deleted. Now this code will only delete the event log if the log is not one of the system logs.

Notice that there is no method that creates only the log, instead you have to call CreateEventSource and create a source as well. However, there is a method, Exists, that you can use to determine if a specified log exists.

Navigate back to the key for the event source you created. There is just one value called EventMessageFile, it has this value:

Before I have a rant about this (which I will, be warned), contrast this with the registry entry that is created for a new performance counter category by the PerformanceCounterCategory class. One of the few criticisms I have for the .NET performance counter classes is that it registers a file without a path and as a consequence it installs the DLL in the %systemroot%\System32 folder, which opens up all kinds of versioning problems. The entry above, created by the EventLog class, does the right thing, it gives a path to the specific version of the event message file used by this application.

At this point unregister the source by running the application with a command line parameter and close down eventvwr (although it is not strictly necessary in this case, it is good practice to close down eventvwr whenever you make changes to the registration of the message file used by a source.).

Unfortunately (and now my rant begins) the EventLogMessages.dll file is braindead and breaks all the rules of the event log. To see how braindead this file is, type the following on the command line (dumpbin is supplied with Visual Studio, it is a shim for the link.exe utility)

Piping through more is necessary because this will dump a lot of data to the command line. First you will see that this command will give information about the section header (on my machine it says that the resource section of this file is 0xc0478) then it will give the version resource (VS_VERSION_INFO), and after that it will give the RT_MESSAGETABLE resource, which you will see as being simply sixty five thousand strings of %1. This is a place holder, equivalent to %s in C or {0} in .NET, in other words, there is no format string and the string read from the event log is the entire message. What lazy programming, this is clearly the work of someone who has no pride whatsoever in their work. Rant over, for the time being.

The overload of CreateEventSource that I used above had two parameters, the name of the source and the name of the log. In the example I used the name of one of the system logs, Application. If you provide a log name that does not exist, the method will create a new log for you (with default values) and create the source in the log. You use DeleteEventSource to delete a source, but this will leave the log file. To delete the log and its associated file call the static method Delete. If you merely want to delete events from a specific log, then you can call Clear on an EventLog instance, however, note that there is no method to allow you to create a backup of the log which is a surprise because there is a Win32 function to do just that (BackupEventLog) so the developer of the EventLog class (who we have already established does not like hard work) would have had very little work to do to supply a method to backup an event log.

Once you know that a source has been registered on a machine you can then write events to the associated log. You usually do this by creating an instance of EventLog passing the name of the machine, log and source. The machine name and source are important, and if the machine name is omitted then the class could assume that the local machine should be used. Specifying the log name is completely pointless because an event source is only associated with one log. The reason that you have to use this constructor is that the EventLog class is designed for both reading and writing events. The constructor that takes two strings has the log name and machine name, and hence is really intended for reading events, similarly the constructor that takes one string is passed the log name and is intended for reading from that log. For writing, this leaves us either the constructor with three strings (as already mentioned) or the default constructor. I prefer this last option because you can specify the source name through the Source property (and if necessary, the machine name through the MachineName property).

Note that you can use any source, and write as that source. Neither the .NET framework, nor the event log API restricts you to writing events only for the sources that you have registered. The only restriction is the security aspect as to whether you are allowed to write to the event log in general. This raises the possibility of a rogue process writing events for another source, which might mislead an administrator using the event log to tune the machine.

One way to create the reference to the event log is to add code like this to a method that writes event messages:

Since the EventLog class is disposable you must close it when it is no longer needed, hence the using statement. The way that this code is written is that the EventLog operation is obtained when the method starts and then closed when the method finishes. Can you see the problem here? The implication is that each method should create an EventLog instance. Obtaining a reference to an event log object is a costly operation, so you should really only perform such an operation infrequently and preferably, just once. This is where the concept of disposable components become important. The EventLog class derives from Component (and hence it implements IDisposable), this means that it provides the following method:

The idea behind this method is that the parameter determines if the component is being disposed, or if it is being finalized. A disposable component must be disposed when it is no longer needed, and then sometime after that, it will be finalized. When a component is disposed it should release both managed and unmanaged resources that it holds, the reason is that some other code has explicitly told the component to dispose itself, so the component must release all the resources it holds. After this the component cannot be reused, but rest assured that it no longer holds any resources. When the component is being finalized there is no need to release the managed resources because they will have been queued to be finalized too, thus only the unmanaged resources should be released, but hopefully the object will already have been disposed so there should not be any extant unmanaged resources.

If you create a component that uses event logging, your component should also be disposable and derive from Component. This means that your component will have a Component.Dispose method which you can use to dispose the EventLog object. Since your component may hold references to several disposable components you will want to dispose all of these at one time. The framework provides a class to do this, Container. This is essentially a collection of Components, but it also implements IDisposable so the Visual Studio designer will typically add the following code to your component:

The first time you add a component to your component through the designer it will add code to create the components object and it will call the Add method to add the component to it.

Since our example is a console application our code is not a disposable object (however, if the code was a Form, it would be) so in our simple example the using technique shown above is fine, but bear in mind that you are unlikely to write code like this yourself.

Add the code shown above (ie the using statement, not the Container code) to the end of the Main method.

Once you have write access to a log you can then use the feculent method WriteEntry to write an event to the log using the specified source name. (Remember, this section is about how Microsoft tells you to write to the EventLog, and is not about the correct way to write to it.) There are ten overloads for this method, two of them are static and have a parameter for the source name. The instance method with the most parameters is shown here:

I know that you are immediately disappointed that there is no string[] argument to provide the replacement strings for the message, instead there is just one single string, message. In .NET 3.0/2.0 the documentation is a little coy about this string:

The WriteEntry method writes the given string directly to the event log; it does not use a localizable message resource file. Use the WriteEvent method to write events using a localized message resource file.

The WriteEntry method should really be marked [Obsolete], or even better, Microsoft should have provided a totally new event log class implemented correctly. This statement is as near as Microsoft gets to admitting that they were completely wrong in  previous versions of the framework for allowing you to write a message that was not localised. In those previous versions you were recommended to localise the string to the culture of the local machine, you were also encouraged to log as much information as possible about the event in the event log (with a warning that each entry should be no more than 16Kb). All of this was rubbish, of course. You should keep the size (in the event log) of each message as small as possible and you should do no localisation at all when logging the event. If the event message needs further information then the user should be directed to another file, but in general you should not do this because the message should not need to give large amounts of data.

The second parameter to the method is this:

The two audit types are only for messages in the Security log, when you log a message it should be one of Information, Warning or Error. As a general rule of thumb before you write an Information or Warning message you should review carefully whether the message is providing any useful information, if not, then do not write the event. It is still possible to write too many Error messages, but this is less likely than for the other two message types.

The third parameter is eventID. The .NET 3.0/2.0 documentation says this:

Event identifiers, along with the event source, uniquely identify an event. Each application can define its own numbered events and the description strings to which they map. Event viewers display these string values to help the user understand what went wrong and suggest what actions to take.

(This is taken from the page for the overload shown above.) The problem is that there is no need for the event ID since the method takes a fully formatted description string. This description is just an excuse for the poor design of the WriteEntry method.

The fourth parameter is called category. The documentation for .NET 3.0/2.0 mentions that you can use this parameter to provide a localised category, which (while true) seems rather odd to me because if you want to use localised category strings then you'll also want to use localised descriptions and hence you will not want to use this method! If you do not provide localisation information (through the steps explained in the next section) then the category will be shown simply as a number. If you provide a localised category then a string will be shown.

The final parameter is an array of bytes. You should use this if there is binary data that is important to the message. However, don't be tempted to misuse this. A few tens of bytes is fine, a hundred bytes is pushing things a bit, but kilobytes of data is definite misuse.

To test out this method, add the following code to the Main method:

This is the sort of chatty messages that you should not generate, but I have included them to illustrate how to write event log messages. If your application is a service (ie very long lived) then an 'application start' - 'application end' pair makes sense. If your application is run several times a day or it lasts for a short amount of time then messages like these just get in the way of useful messages.

Compile this code and run it. Now start eventvwr, you will see that there is a log called TestLog and within that log are two messages from the Acme_Source.

Now here's a peculiarity of the event log service. If the source name has a space in it (eg Acme Source) then messages will always be logged to the Application log regardless of the log that you specified in CreateEventSource. This means that if the source was created in a different log then when it comes to formatting the message the event log viewer will not find the source (and hence the source message file) under the Application key and so it will not be able to format the message. This leads to the peculiarity that custom logs can only have sources that do not have spaces in their name (which is why I called the source Acme_Source).

Just to illustrate why chatty logs are bad, add the following code:

The idea here is that the routine creates lots of trivial messages, but very occasionally it creates an important message. I have rather helpfully made the message types different so that you can identify them in the event log viewer, but in practice, with a real application, this is unlikely to be the case.

Compile this code. Run the application with a parameter (to de-register), close down eventvwr, run the application without a parameter to re-register the source and then again to log the messages. Start eventvwr and take a look in the TestLog. log. You should find that the log has now filled up with trivial messages. Scroll through and try and find the important message. Not easy, is it? you may find that the gods playing dice behind the Random class have not given you a value to generate an important message, if this is the case run the application again and refresh the view in eventvwr by pressing F5.

What you should have got from this exercise is that chatty, trivial messages will make it difficult to see important messages. Do not do this!

Let's try another thing. Let's increase the size of the trivial messages. This is easy to do, add the following:

Compile this code.

In eventvwr right click on TestLog in the left hand tree and select Clear all events. Answer No to the question about whether you should save the log. Now right click again on TestLog in the left hand tree and select Properties. In the dialog change the Maximum log size to 64kb (the minimum allowed) and select Overwrite events as needed. Close the dialog by clicking on OK.

Now run the code without a parameter so that it generates lots of messages. You know that the oldest message should have an event ID of 0 indicating that the application has started, the last message should have an event ID of 1 indicating that the application has ended. Refresh the view in the event log viewer and scan through the messages. At the top you'll find the message with an event ID of 1, so scroll down to the bottom and see what is the event ID of the oldest message. It will be 3 (or if you are lucky 2) but it will certainly not be 0. So where has the first message gone? Well the event log file has been set to a small value and the messages are large-ish, so sometime during the loop the event log has been filled and so the event log service has overwritten the older messages with the new ones. What if the message with an event ID of 0 is an important message? You have lost it and had no opportunity to read it. You could argue that you could have made the log large enough to hold all the messages that you will find useful, but how do you decide how big that is? If your application logs to the Application log (which is usually the best idea because you can see the relationship between messages from all applications) how do you know the other applications on the machine will behave?

In this case you have seen that chatty, trivial messages have been damaging, they have resulted in an important message being deleted before it could be read. I hope you should realise now that chatty, trivial messages have no place in the event log.

Incidentally, the settings on the log's property page can be changed through the EventLog class. The main way is through a method call ModifyOverflowPolicy:

This allows you to determine what happens when the log gets filled (DoNotOverwrite, OverwriteAsNeeded, OverwriteOlder) and if the latter is selected, how old a message has to be before it is overwritten. The OverflowAction and MinimumRetentionDays properties can be used to set the same values. Furthermore, there is a property called MaximumKilobytes that can be used to programmatically change the log size.

Go back to the property page of TestLog and change the overwrite property to Do not overwrite events. At this point the log should be full, so run the application again and see what happens. You should find that the application will throw a Win32Exception with the description The event log file is full. (If you indicate that older messages should be overwritten then you'll get the same exception.) Note that the event log service simply does not log the event, and that's all. A message in the System log indicating that the source's log was full might have been useful but the decision was taken not to do this because if the situation is not resolved then these messages in the System log will fill up that log!

Clearly the retention policy and the size of the log are important and using wrong values not only result in lost event log messages, but they can cause an exception to be thrown in the application, not just your application, but any application that writes to the log! Imagine that your application is correctly written and is considerate: it only logs important messages. How annoyed will you be to find that it fails because someone else's application filled the event log with trivial, chatty messages? Annoyed enough to uninstall their application and never again buy their software? (I hope so.)

Finally, for this example, run the application again with a parameter to remove the source and the log.

I hope that you enjoy this tutorial and value the knowledge that you will gain from it. I am always pleased to hear from people who use this tutorial (contact me). If you find this tutorial useful then please also email your comments to mvpga@microsoft.com.

Errata

If you see an error on this page, please contact me and I will fix the problem.

Page Eight continued