How to elegantly log contextual information along with every message

Question

I'm looking for some advice on logging. I've written a wrapper called Logger which internally uses Microsoft Enterprise Library 5.0. Currently it enables us to log in this way:

Logger.Error(LogCategory.Server, "Some message with some state {0}", state);

The problem I face is that every log in the EventViewer seems to be unrelated even though some of them are somehow related, for example they all come from processing a request from a particular client.

Let me elaborate on the problem. Suppose I'm working on a service which needs to handle requests from multiple clients at the same time, each passing different set of parameters to the service methods. Few of the parameters can be used to identify the requests, such as which client is making what kind of request with what uniquely identifiable parameters, etc. Say these parameters are (call the contextual information):

• ServerProfileId
• WebProfileId
• RequestId
• SessionInfo

Now the service started processing the requests, doing one thing after another (like a workflow). In the process I'm logging local¹ messages such as "file not found" or "entry not found in DB", but I don't want to manually log the above information (the contextual information) with every log, rather I want the logger to log them automatically every time I log local message:

Logger.Error(LogCategory.Server, "requested file not found");

And I want the above call to log the contextual information along with the message "requested file not found" so I can relate the message with its context.

The question is, how should I design such a logger wrapper which logs contexts automatically? I want it to be flexible enough, so that I may add more specific contextual information along the way the service processes the request, as all the important information may not be available in the beginning of the request!

I also want to make it configurable, so I can log the local messages without logging the context information, as they're not needed when everything works great. :-)

---

^{1. By local message I mean the messages which is more specific, local in nature. By contrast, I would say, the contextual informations are the global messages, as they make sense for the entire flow of processing a request.}

Answer 1

Here is one approach that uses Enterprise Library that is fairly easy to setup. You can use Activity Tracing for storing global context and Extended Properties for storing local context.

For the sake of an example I'll use a service locator without any wrapper class to demonstrate the approach.

var traceManager = EnterpriseLibraryContainer.Current.GetInstance<TraceManager>();

using (var tracer1 = traceManager.StartTrace("MyRequestId=" + GetRequestId().ToString()))
using (var tracer2 = traceManager.StartTrace("ClientID=" + clientId))
{
    DoSomething();
}

static void DoSomething()
{
    var logWriter = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();
    logWriter.Write("doing something", "General");

    DoSomethingElse("ABC.txt");
}

static void DoSomethingElse(string fileName)
{
    var logWriter = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();

    // Oops need to log
    LogEntry logEntry = new LogEntry()
    {
        Categories = new string[] { "General" },
        Message = "requested file not found",
        ExtendedProperties = new Dictionary<string, object>() { { "filename", fileName } }
    };

    logWriter.Write(logEntry);
}

The configuration would look like this:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <configSections>
        <section name="loggingConfiguration" type="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.LoggingSettings, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.505.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" requirePermission="true" />
    </configSections>
    <loggingConfiguration name="" tracingEnabled="true" defaultCategory="General"
        logWarningsWhenNoCategoriesMatch="false">
        <listeners>
            <add name="Flat File Trace Listener" type="Microsoft.Practices.EnterpriseLibrary.Logging.TraceListeners.FlatFileTraceListener, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.505.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
                listenerDataType="Microsoft.Practices.EnterpriseLibrary.Logging.Configuration.FlatFileTraceListenerData, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.505.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
                fileName="trace.log" formatter="Text Formatter" traceOutputOptions="LogicalOperationStack" />
        </listeners>
        <formatters>
            <add type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=5.0.505.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35"
                template="Timestamp: {timestamp}&#xA;Message: {message}&#xA;ActivityID: {activity}&#xA;Context: {category}&#xA;Priority: {priority}&#xA;EventId: {eventid}&#xA;Severity: {severity}&#xA;Title:{title}&#xA;Machine: {localMachine}&#xA;App Domain: {localAppDomain}&#xA;ProcessId: {localProcessId}&#xA;Process Name: {localProcessName}&#xA;Thread Name: {threadName}&#xA;Win32 ThreadId:{win32ThreadId}&#xA;Local Context: {dictionary({key} - {value}{newline})}"
                name="Text Formatter" />
        </formatters>
        <categorySources>
            <add switchValue="All" name="General">
                <listeners>
                    <add name="Flat File Trace Listener" />
                </listeners>
            </add>
        </categorySources>
        <specialSources>
            <allEvents switchValue="All" name="All Events" />
            <notProcessed switchValue="All" name="Unprocessed Category" />
            <errors switchValue="All" name="Logging Errors &amp; Warnings" />
        </specialSources>
    </loggingConfiguration>
</configuration>

This will result in an output like this:

----------------------------------------
Timestamp: 1/16/2013 3:50:11 PM
Message: doing something
ActivityID: 5b765d8c-935a-445c-b9fb-bde4db73124f
Context: General, ClientID=123456, MyRequestId=8f2828be-44bf-436c-9e24-9641963db09a
Priority: -1
EventId: 1
Severity: Information
Title:
Machine: MACHINE
App Domain: LoggingTracerNDC.exe
ProcessId: 5320
Process Name: LoggingTracerNDC.exe
Thread Name: 
Win32 ThreadId:8472
Local Context: 
----------------------------------------
----------------------------------------
Timestamp: 1/16/2013 3:50:11 PM
Message: requested file not found
ActivityID: 5b765d8c-935a-445c-b9fb-bde4db73124f
Context: General, ClientID=123456, MyRequestId=8f2828be-44bf-436c-9e24-9641963db09a
Priority: -1
EventId: 0
Severity: Information
Title:
Machine: MACHINE
App Domain: LoggingTracerNDC.exe
ProcessId: 5320
Process Name: LoggingTracerNDC.exe
Thread Name: 
Win32 ThreadId:8472
Local Context: filename - ABC.txt

----------------------------------------

Things to note:

• Since we are using tracing we get the .NET activity ID for free which can be used to correlate activities. Of course we can use our own context information as well (custom request ID, client ID, etc.).
• Enterprise Library uses the tracing "operation name" as a category so we need to set logWarningsWhenNoCategoriesMatch="false" otherwise we'll get a flurry of warning messages.
• A downside of this approach may be performance (but I haven't measured it).

If you want to disable global context (which is, in this implementation, tracing) then all you need to do is edit the configuration file and set tracingEnabled="false".

This seems to be a fairly straight forward way to achieve your objectives using built-in Enterprise Library functionality.

Other approaches to consider would be to potentially use some sort of interception (custom LogCallHandler) which can be quite elegant (but that might depend on the existing design).

If you are going to go with a custom implementation to collect and manage context then you could consider looking at using Trace.CorrelationManager for per thread context. You could also look at creating an IExtraInformationProvider to populate the extended properties dictionary (see Enterprise Library 3.1 Logging Formatter Template - Include URL Request for an example).

Answer 2

Disclaimer: I do not know the specifics of Microsoft technical stack.

What I would do in this case is something along the lines of:

Implement a Singleton (at the server instance level, it does not need to be a global singleton in case your app is deployed to a cluster) which is basically a sort of Hashmap where "Key" is a uniquely meaningful identifier for the request you are processing. In Java I'd use the thread-id (assuming you serve the request by dispatching a thread from a thread pool). If this is impossible/does not make sense in your case, you have to use the Request ID (but in this case you have to make it percolate down to the log manager, while my idea would be to use something that is intrinsically available in the thread itself).

The "value" for the Hashmap will be a set of data - in your case ServerProfileId, WebProfileId, RequestId (unless it's already the key), SessionInfo - so that the logmanager can conditionally retrieve these and pick up the parts that are meaningful for a specific log event.

So: create a globally available reference to request state at the start of the request management, and make sure that the logging manager can retrieve request state when needed.

Of course you have to make sure that the hashmap is correctly managed (by removing state after a request has been disposed with).