Logging and Tracing in the Stock Trader V2

Retired Content
This content is outdated and is no longer being maintained. It is provided as a courtesy for individuals who are still using these technologies. This page may contain URLs that were valid when originally published, but now link to sites or pages that no longer exist.
The latest Enterprise Library information can be found at the Enterprise Library site.

On this page:
Stories for Logging and Tracing - IT Operations Should Be Able to View Errors in a Centralized Way, Power Users Should Be Able to See Critical Logging Information, Users Should Be Able to Increase Their Logging Levels at Run Time, Developers Should Be Able to See Detailed Tracing Information, Being Able to Correlate Log Messages with Activities

It is time to discuss how diagnostic logging and tracing were implemented in the StockTrader V2 reference implementation. The first version of the Stock Trader didn't have very good diagnostic logging and tracing functionality. This caused a number of unfortunate side effects:

• The IT organization usually didn't know about problems with the old Stock Trader until unhappy users reported them.
• Problems reported by users were often difficult to reproduce. Only a very limited amount of diagnostic data was generated by the application.
• When a power user ran into a problem with the old Stock Trader, he couldn't get access to any diagnostic information either. Given more information, these users are sometimes able to solve issues by themselves (if the problem was on their own computer) or at least be able to help the IT organization analyze the problem.

Stories for Logging and Tracing

In this section, we'll discuss the most important stories for logging and tracing, and how they were implemented in Stock Trader V2.

Mark Says:

When we began designing Stock Trader V2, we didn't want logging and tracing to become an afterthought. Rather we wanted to make it a first-class requirement in our planning. To do this, we defined several stories around diagnostic logging and tracing, with different actors, such as a user, a developer, or somebody from IT operations. These stories were planned, developed and (acceptance) tested along with the other functional stories for Stock Trader V2. </td>

IT Operations Should Be Able to View Errors in a Centralized Way

IT operations needs a centralized way to record, detect, and view problems that occur with the entire Stock Trader V2 application. This means that problems that occur within the Silverlight client and problems that occur only within the server should be recorded in a central location.

Mark Says:

There are many ways in which you can realize a centralized method for recording and viewing problems that occur within an application. For example, you can log to a central database and build an application that monitors this database. <br />In our organization, we already use System Center Operations Manager to monitor the Event Logs of our servers. When a problem occurs, such as an unhandled exception or warning, our IT staff is notified of this problem and we can start to investigate it. We also wanted this capability for the Silverlight front end of Stock Trader V2. </td>

Errors and warnings that occur in the Silverlight client need to be sent back to the web servers, where they should be added to the Windows Event Log. From there, they can be picked up by System Center Operations Manager.

The following diagram illustrates how warnings, errors, and critical messages are recorded to the Windows Event Log of the server:

In Stock Trader V2, exception handling is performed by the Exception Handling Application Block. This block is configured so that certain types of exceptions are logged using the Logging Application Block, with an appropriate log severity. There are also many explicit calls to the Log Writer in the Stock Trader. For example, log messages are written when the user clicks a button, when a validation error occurs, and when a web service successfully completes.

In Stock Trader V2's configuration file (StockTraderRI.Configuration.xaml), the logging application block is configured so that log messages with a severity of Warning, Error, or Critical are sent to the Remote Service trace listener. This listener will send log messages to the log service on the web server.

To prevent log messages from getting lost if there are connection issues, log messages will also be buffered in isolated storage. This way the log messages will even be sent if the application has crashed completely and is restarted.

On the web server, any log messages that are received by the log service will be sent to the Logging Application Block, which is configured to send all log messages with a severity of Warning, Error, or Critical to the event log.

Power Users Should Be Able to See Critical Logging Information

Some of the users of Stock Trader V2 are advanced computer users. They would like to be able to see the information that's logged by Stock Trader V2. When a problem occurs in the application, they want to see what exactly is going wrong. Sometimes, they are able to solve the issue. If not, they are able to provide the IT organization with additional information.

The following diagram shows how this is solved in Stock Trader V2:

In the configuration file (StockTraderRI.Silverlight.xaml) it's defined that log messages with a severity of Warning, Error, or Critical will be stored in isolated storage, by using the Isolated Storage Trace Listener. A custom view, called the Isolated Storage Log View, was built to read and display these log messages from isolated storage. It can read log messages from the Isolated Storage Log Entry Repository. Since this feature is only available for power users, we decided that it doesn't need a menu item, but can be accessed when you add #IsolatedStorageLog to the URL in the browser. In this view, the users should be able to copy the contents of a log entry to the clipboard so that it can easily be sent to IT operations.

The isolated storage is by default only 1 Mb in size. Therefore Stock Trader V2 at startup asks for more isolated storage space. If the user approves this request, then the size of the log file is increased.

Users Should Be Able to Increase Their Logging Levels at Run Time

When a user has a particular problem in production that is difficult to reproduce, it should be possible for that user to increase the logging levels of the application at run time. This means that more log diagnostic information will be sent back to the server. This can help to diagnose a problem with a particular user.

Mark Says:
	In a future version of the Stock Trader, we’ll likely want to include an option to increase the logging settings for a particular user from the server side. For now, this option is sufficient.</td>

Developers Should Be Able to See Detailed Tracing Information

While developing or maintaining Stock Trader V2, developers need the ability to see more detailed tracing information. This information should be visualized as the application is running. If a problem occurs, this information can help the developer to more quickly understand a particular problem.

The following diagram shows how this was implemented in Stock Trader V2:

In the Stock Trader V2's configuration file, the All Events Trace Source has been set to use the Notification trace listener. This means that all log messages are sent to this trace listener. When a message is logged, the trace dispatcher will raise an event. The Trace Log View Model listens for these events and will display all received messages.

Being Able to Correlate Log Messages with Activities

Developers and IT professionals would like the ability to group log messages by activity or category. When a problem occurs while executing a particular activity, they can easily see which other log messages were also part of that same logical activity. For example:

• Which log entries were the direct result of a particular button click?
• Which log entries were generated on a particular screen?

When you create a tracer, any log message that is written until that tracer is disposed will be associated with that tracer. A tracer has both an activity ID and an associated category name, so all log messages that will be written during the lifetime of that tracer will also get that activity ID and category name associated. For more information about creating tracers, please refer to the chapter on Creating Tracers.

Creating a tracer for synchronous operations is fairly straightforward. However, for asynchronous actions, you'll have to take additional steps to have the tracing context transferred to the new thread. Just before you start a new asynchronous action, you'll need to capture the tracing context in a variable. Then, on the new thread, you can restore the tracing context. Since all web service actions are asynchronous in Silverlight, there are many circumstances in which you might run into this situation.

Consider the following example. You want to load a particular account holder (let's say, account holder 621). Before you call the load account holder web service, a log message is written that you are about to load account holder 621. When the web service call returns, it throws an exception; for example: "Account holder could not be found." This exception is also logged, but since it does not mention which account holder could not be found, it can be difficult to debug. With a synchronous action, you can easily use a tracer to correlate these two log messages. With asynchronous actions, you can also use tracers, though you will need to take additional steps.

Ed Says:
	On the desktop version of the .NET Framework, the tracing context automatically inherits newly started threads. Silverlight does not support this, so we needed to add extra logic to capture the tracing context just before the asynchronous action starts and restore it on the new thread. </td>

The Silverlight Logging Application Block allows you to capture the tracing context into an object, just before you start an asynchronous action. Most asynchronous actions allow you to pass an object as user state. This object is then returned when the asynchronous action completes. You can then pass the captured context to the asynchronous action as the user state and use it to restore the captured tracing context when the request completes.

The following code block shows a slightly simplified example of how this is implemented in Stock Trader V2.

public void LoadAccountHolder()
{
    // Create a tracer that groups all log messages together
    using (logWriter.StartTrace("LoadAccountHolder", Guid.NewGuid()))
    {
        // Capture the context just before the async action starts
        var capturedContext = Tracer.CaptureTracingContext();
        // Pass the captured tracing context as user state to the async action
        accountHolderServiceAgent.GetAccountHolder(LoadAccountHolderComplete,
            capturedContext);
    }
}

private void LoadAccountHolderComplete(ServiceResult<AccountHolder> serviceResult)
{
    // On the callback, retrieve the captured tracing context from the user state
    var capturedContext = serviceResult.UserState as ICapturedTracingContext;

    // Restore the tracing context
    using (capturedContext.Restore())
    {
        // Any log message that is written here is associated with the 
        // same tracing context as in the LoadAccountHolder method
    }
}

Next Topic | Previous Topic | Home

Last built: July 8, 2011