Using Request Ids to correlate JavaScript and server side log messages

Implementing request ids for Log4Net

Getting Log4Net to prepend the request id to each log message takes two steps: 1) tell Log4Net to include the request id in log messages; and 2) tell Log4Net the current request id.

Tell Log4Net to include the request id in log messages

Log4Net allows you to specify the fields in your log messages, using layout elements in your web.config. A common layout looks like this:

<log4net>
    <appender .....>
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%utcdate | %level | %logger | 
                %message%newline" /> 
        </layout>
    </appender>
</log4net>

To have Log4Net include the request id, add a custom property requestId to the layout:

<log4net>
    <appender .....>
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%property{requestId} | %utcdate | 
                %level | %logger | %message%newline" /> 
        </layout>
    </appender>
</log4net>

Note that each log message now starts with first the request id and than the date and time. This way, when you sort the log messages, you get a chronological history per page request.

Tell Log4Net the current request id

Setting the requestId property requires a few steps:

• Log4Net allows you to set custom properties using Context Properties, which looks like this:

  log4net.GlobalContext.Properties["name"] = value;
  

• You need to pass the current request id to Log4Net before any logging is done. That is, at the very start of request processing. A good place would be the Application_BeginRequest handler in Global.asax.cs.
• You also need the request id. JSNLog exposes the method JavascriptLogging.RequestId for this purpose. For page requests, it generates a new request id and returns that. If you call it multiple times during the same page request, it returns the same value. For log requests from jsnlog.js, it returns the request id that was included in the log request.
• Finally, Log4Net has to be initialized after the custom property has been set, using the line:

  log4net.Config.XmlConfigurator.Configure();

Putting it all together, simply add this Application_BeginRequest handler to your global.asax.cs:

protected void Application_BeginRequest()
{
    log4net.GlobalContext.Properties["requestId"] = 
        JSNLog.JavascriptLogging.RequestId();
    log4net.Config.XmlConfigurator.Configure();
}

As with Log4Net, getting NLog to prepend the request id to each log message takes two steps: 1) tell NLog to include the request id in log messages; and 2) tell NLog the current request id.

Tell NLog to include the request id in log messages

NLog lets you specify the fields in your log messages as part of the target specification in your web.config. A common layout looks like this:

<nlog ... >
    <targets>
        <target layout="${longdate} ${level:padding=-30} 
            ${logger:padding=-30} ${message} ${exception:format=tostring}" 
            ... />
    </targets>
</nlog>

To have NLog include the request id, add a custom property requestId to the layout:

<nlog ... >
    <targets>
        <target layout="${mdc:item=requestId} ${longdate} 
            ${level:padding=-30} ${logger:padding=-30} ${message} 
            ${exception:format=tostring}" ... />
    </targets>
</nlog>

Note that each log message now starts with first the request id and than the date and time. This way, when you sort the log messages, you get a chronological history per page request.

Tell NLog the current request id

Setting the requestId property requires a few steps:

• NLog allows you to set custom properties using its MappedDiagnosticsContext. This looks like this:

  NLog.MappedDiagnosticsContext.Set("name", value);

• You need to pass the current request id to NLog before any logging is done. That is, at the very start of request processing. A good place would be the Application_BeginRequest handler in Global.asax.cs.
• Finally, you need the request id. JSNLog exposes the method JavascriptLogging.RequestId for this purpose. For page requests, it generates a new request id and returns that. If you call it multiple times during the same page request, it returns the same value. For log requests from jsnlog.js, it returns the request id that was included in the log request.

Putting it all together, simply add this Application_BeginRequest handler to your global.asax.cs:

protected void Application_BeginRequest()
{
    NLog.MappedDiagnosticsContext.Set("requestId", 
        JSNLog.JavascriptLogging.RequestId());
}

Implementing request ids for Elmah

Elmah is not as configurable as Log4Net and NLog. The only way to add the request id is to simply prepend it to the log message.

To do this for log messages from the client, set the serverSideMessageFormat attribute of the JSNLog configuration element:

<jsnlog serverSideMessageFormat="%requestId | %logger | %level | %message">
</jsnlog>

JavascriptLogging.SetJsnlogConfiguration(
  new JsnlogConfiguration {
      serverSideMessageFormat="%requestId | %logger | %level | %message"
  });

You will want to make the request id the very first field, so you can sort on it later.

If you use Elmah to log messages in your server side code, you could add request ids to those messages by introducing a new method that always prepends the request id to the log message:

using Elmah;

...

LogToElmah("The log message");

...

public void LogToElmah(string message)
{
    string requestId = JSNLog.JavascriptLogging.RequestId();
    Elmah.ErrorSignal.FromCurrentContext().Raise(new Exception(
        string.Format("{0} | {1}", requestId, message)));
}

Elmah lets you download the log messages from the elmah.axd page, and it also lets you store them in a file or database. You can sort the log entries by message and then timestamp (stored by Elmah in a separate field), to get the log messages grouped by user session in chronological order.

Keep in mind though that if there is an uncaught exception and Elmah logs that exception, it won't have the request id.

Implementing request ids for Serilog

Similar to Elmah, Serilog is not as configurable as Log4Net and NLog. The only way to add the request id is to add it to the log message as it is being stored in the server side log.

To make that happen, set the serverSideMessageFormat attribute of the JSNLog configuration element:

<jsnlog serverSideMessageFormat=
    "{ 'requestId': '%requestId', 'clientdate': '%date', 'url': '%url', 'logmessage': %jsonmessage }">
</jsnlog>

JavascriptLogging.SetJsnlogConfiguration(
  new JsnlogConfiguration {
      serverSideMessageFormat=
          "{ 'requestId': '%requestId', 'clientdate': '%date', 'url': '%url', 'logmessage': %jsonmessage }"
  });

Note that by writing this as a JSON object (with the { and } at beginning and end), you allow the log information to be logged as separate fields, making it easier to search and order log messages.

If you use Serilog's MongoDB sink to log to a MongoDB database, you would use the following command in the mongo shell to sort your log entries by request id and then by date/time. That way, you get a history of each page request and the JavaScript events on that page after it reached the client.

db.log.find(undefined, {Properties: 1, _id: 0})
      .sort( { 'Properties.message.requestId': -1, 'Properties.message.clientdate': 1 } )

More about logging to Serilog and MongoDB:

• Structured JavaScript Logging
• Sorting results with the mongo shell
• Filtering results with the mongo shell