How To

Using Request Ids to correlate JavaScript and server side log messages

A working demo is in project JSNLogDemo_NLog_NetCoreRequestId

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

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 NLog

NLog lets you specify the fields to include in each line in your log via the layout property in the target specification.

Add the request id to the start of the layout. You'd wind up with something like this:

<target .....
 layout="${aspnet-request:header=JSNLog-RequestId:whenEmpty=${aspnet-TraceIdentifier}}|${longdate}|${message}" />

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.