Documentation Menu

Using Request Ids to correlate JavaScript and server side log messages

This page first shows why you'd use request ids, and then how to implement them for Log4Net, NLog, Elmah and Serilog.

Concurrent accesses lead to intermingled log entries

Many pages are JavaScript heavy - there is one request to the server to load the page, and then all button clicks, etc. are handled with JavaScript code.

JSNLog makes it easy to log events in your JavaScript code. But what if multiple users load the same page and then interact with it at the same time? Log messages from those pages will be intermingled.

Take this log, showing messages from both server side and JavaScript loggers:

2014-04-22 09:55:09,897 | INFO | serverlogger | Request for client page, 
    id=5, city=Washington
2014-04-22 09:55:22,762 | DEBUG | ClientRoot | Clicked button "Details"
2014-04-22 09:55:22,898 | DEBUG | ClientRoot | Clicked button "More"
2014-04-22 09:56:11,255 | INFO | serverlogger | Request for client page, 
    id=45, city=London
2014-04-22 09:56:16,699 | INFO | serverlogger | Request for client page, 
    id=7, city=Paris
2014-04-22 09:56:31,251 | DEBUG | ClientRoot | Clicked button "Details"
2014-04-22 09:56:36,058 | DEBUG | ClientRoot | Clicked button "Save"
2014-04-22 09:56:36,202 | ERROR | ClientRoot | Invalid 
    url http://domain.com/x$?

Obviously, the last log message shows something went wrong. And the other messages show potentially useful information, both from the server and the clients. But which messages are associated with the same page request as the error message?

Request ids show which log messages belong together

JSNLog allows you to add request ids to each log message, whether produced on the server or the client. Each request to the server has its own unique id. When the page is sent to the client, JSNLog inserts the request id in the page in a bit of JavaScript code, so the jsnlog.js library can send it back in each log request.

With request ids, the log that you saw above now looks like this. To make things clearer, lines with the same request id have been given the same background color (the colors won't appear in your actual logs):

00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:09,897 | info | 
    serverlogger | request for client page, id=5, city=Washington
00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:22,762 | debug |      
    clientroot | clicked button "Details"
00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:22,898 | debug |      
    clientroot | clicked button "More"
00000000-0000-0000-7a01-0080000000fb | 2014-04-22 09:56:11,255 | info |      
    serverlogger | request for client page, id=45, city=London
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:16,699 | info |      
    serverlogger | request for client page, id=7, city=Paris
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:31,251 | debug |      
    clientroot | clicked button "Details"
00000000-0000-0000-7a01-0080000000fb | 2014-04-22 09:56:36,058 | debug |      
    clientroot | clicked button "Save"
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:36,202 | error |      
    clientroot | invalid url http />/domain.com/x$?

Sort to quickly see what happened for each page request

If you now sort the log entries in alphabetical order, you get a history of each page request and the JavaScript events on that page after it reached the client. If your logs are in files, you could sort them from the command line using the sort command:

sort log.txt >sortedlog.txt

You will wind up with something like this. You should now be able to track the server side events and client side JavaScript events related to each page load, even with dozens of users interacting with your pages at the same time.

00000000-0000-0000-7a01-0080000000fb | 2014-04-22 09:56:11,255 | info |      
    serverlogger | request for client page, id=45, city=London
00000000-0000-0000-7a01-0080000000fb | 2014-04-22 09:56:36,058 | debug |      
    clientroot | clicked button "Save"
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:16,699 | info |      
    serverlogger | request for client page, id=7, city=Paris
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:31,251 | debug |      
    clientroot | clicked button "Details"
00000000-0000-0000-9103-0080000000fd | 2014-04-22 09:56:36,202 | error |      
    clientroot | invalid url http />/domain.com/x$?
00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:09,897 | info | 
    serverlogger | request for client page, id=5, city=Washington
00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:22,762 | debug |      
    clientroot | clicked button "Details"
00000000-0000-0000-ea00-0080000000fa | 2014-04-22 09:55:22,898 | debug |      
    clientroot | clicked button "More"

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();
}

Implementing request ids for NLog

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> / JsnlogConfiguration 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> / JsnlogConfiguration 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:

Why not use IP addresses instead of request ids?

Simply logging the IP address of each request would be simpler than doing all this work to log request ids. However:

  • Many users share the same IP address (why).
  • A user could open the same page in two browser windows and interact with them at the same time. The IP addresses would be the same, but the request ids would be different.