“HttpContext is not thread-safe. Reading or writing properties of the HttpContext outside of processing a request can result in a NullReferenceException.” (from docs.microsoft.com)

I am a big fan of Elasticsearch (ELK) logging and have built this into the Ioka.Services.Foundation using the Serilog libary, my current favorite .NET Core logging library. There are many ways to approach this and my intent is not to explore those but to show one way of taking on the task of logging in a background thread while preserving some request context detail in your log.

Following the recommendation on the above docs page, we copy the elements of the HttpContext that we need for our background thread logging using the LogContextFactory. Here’s a snippet of that code. For your scenario, you’ll want to modify what values you wish to preserve and you may wish to remove the fairly heavy duty user agent parser if you don’t care about seeing user agent data broken down in the log message.

public static LogContext Create(HttpContext context)
{
   return CreateFactory(() => context)();
}

public static Func CreateFactory(Func httpContextFactory)
{
   if (null == httpContextFactory) throw new ArgumentNullException(nameof(httpContextFactory));
   return new Func(() =>
   {
      try
      {
         var httpCtx = httpContextFactory();
         var httpRequestFeature = httpCtx.Request.HttpContext.Features.Get();
         var context = new LogContext();
         context["_ThreadId"] = Environment.CurrentManagedThreadId.ToString(); 
         context["_Source"] = Assembly.GetEntryAssembly().GetName().Name;
         context["_IpAddress"] = httpCtx.Connection.RemoteIpAddress.ToString();
         context["_UserId"] = httpCtx.Request.Headers["APPUID"].Count > 0 
            ? httpCtx.Request.Headers["APPUID"][0] 
            : context["_UserId"];
         context["_HttpMethod"] = httpCtx.Request.Method;

In the controller we call the Create method to get a copy of what we need to pass into the background thread async method called DoMathWithLogging (cheesy name for demo purposes only) like this:

public async Task<ActionResult<IEnumerable<string>>> Get()
{
    var msg1 = "Another message";
    var msg3 = new CustomError { Name = "Second", Message = "Second other message" };
    _logger.Debug("This is a debug message. {msg1}, {@msg3}", msg1, msg3);

    var logContext = LogContextFactory.Create(this.HttpContext);
    var result = await _mathDemoProvider.DoMathWithLogging(logContext, _logger);

    return new string[] 
    {
        logContext["_UserId"],
        logContext["_RequestId"],
        result.ToString()
    };
}

Now in the DoMathWithLogging method, we use the ILog interface With method to pass the LogContext object into the logger to preserve what we have copied from HttpContext to the LogContext object.

public async Task<long> DoMathWithLogging(LogContext logContext, ILog logger)
{
    long x = 0;
    try
    {
        var rand = new Random();
        for (int i = 0; i < 10; i++)
        {
            x = 1000 * (long)rand.NextDouble();
            Thread.Sleep(10);
        }
        Thread.Sleep(100);
        var c = 0;
        x = 77 / c;
    }
    catch (Exception e)
    {
        //uses new logger with saved context as this 
        //is not on the request background thread
        logger.With(logContext).Error(e, "Error: value of {LargeValue}", x);
    }
    return x;
}

Note that in our demo code, we deliberately throw a divide by zero error and log it. And now in the implementation of the With method looks like this, capturing the current thread in the “_ThreadId-With” property on the context.

public ILog With(LogContext context)
{
    context["_ThreadId-With"] = Environment.CurrentManagedThreadId.ToString();
    var list = _enrichers.Where(x => x.GetType() != typeof(LogEnricher)).ToList();
    list.Insert(0, new LogEnricher(context, null));
    return new Log(_config, _level, () => _index, _failureSink, _failureCallback, list.ToArray());
}

In the With method, we insert a new log enricher for the Serilog logger. This allows us to capture the copied context values in the log messages, such as the Error logged like this:

{
  "_index": "test",
  "_type": "logevent",
  "_id": "JAdXF2oB9fWPG6gy8H_9",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2019-04-13T15:36:40.2296224+00:00",
    "level": "Error",
    "messageTemplate": "Error: value of {LargeValue}",
    "message": "Error: value of 0",
    "exception": {
      "Depth": 0,
      "ClassName": "",
      "Message": "Attempted to divide by zero.",
      "Source": "Ioka.Services.Demo",
      "StackTraceString": "   at Ioka.Services.Demo.Providers.MathLoggingDemoProvider.DoMathWithLogging(LogContext logContext, ILog logger) in D:\\Code\\Github\\Ioka.Services.Foundation\\src\\Ioka.Services.Demo\\Providers\\MathLoggingDemoProvider.cs:line 30",
      "RemoteStackTraceString": "",
      "RemoteStackIndex": -1,
      "HResult": -2147352558,
      "HelpURL": null
    },
    "fields": {
      "LargeValue": 0,
      "_UserId": "root",
      "_IpAddress": "::ffff:172.18.0.1",
      "_Source": "Ioka.Services.Demo",
      "_MachineName": "6cf7fdb5f3cf",
      "_ThreadId": "14",
      "_HttpMethod": "GET",
      "_RequestId": "50d32de9-df69-4aee-ae48-075f22b8ac2d",
      "_Url": "https://localhost:44370/api/Values",
      "_Query": "Microsoft.AspNetCore.Http.Internal.QueryCollection",
      "_WebUser": null,
      "_Browser": "Chrome 73.0.3683 Windows 10",
      "_Header_Connection": "keep-alive",
      "_Header_Accept": "text/plain",
      "_Header_Accept-Encoding": "gzip, deflate, br",
      "_Header_Accept-Language": "en-US,en;q=0.9",
      "_Header_Host": "localhost:44370",
      "_Header_Referer": "https://localhost:44370/api-docs/index.html",
      "_Header_User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/73.0.3683.103 Safari/537.36",
      "_ThreadId-With": "14"
    }
  },
  "fields": {
    "@timestamp": [
      "2019-04-13T15:36:40.229Z"
    ]
  },
  "sort": [
    1555169800229
  ]
}

Note the "_ThreadId-With" property above has the same vs!he as the request thread is. This is because not all async methods will run on a background thread. In previous versions of this code, I forced a long running task to spin up on another thread to verify this. Generally I would not recommend that in practice.

Also note the "_RequestId" property which would allow you to filter in Kibana for all entries with that value in order to trace all log entries for a given request. This can be a very useful tool when you're trying to figure out what happened.

This is the first of many upcoming posts on the code and use of the Ioka.Services.Foundation. The code base is not intended for production use but to provide a guide when you create your own internal libraries to spin up a set of .NET Core microservices that have a common set of fundamental elements that will make working on them, supporting them and using them easier.