“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.

I know JSON Web Tokens (JWT) have been around for a while, but I still run into many developers who do not know much or anything about them. You can read much more in the JWT Handbook and at one of my favorite online tool sites for using JWT at jwt.io.

Here are the 5 things I think you should know about JWT:

#1. OpenID

If you're not already using OpenID, a standard for single sign-on and identity provision, you should be looking into it. There are many sites where you can learn more about OpenID. The connect2id.com OpenID overview is a good place to start. And if you're using ASP.NET Core 2 and IdentityServer4, you definitely want to know more about JWT and OpenID.

#2. Security Concerns

You can encrypt your JWT tokens but most do not. You can include whatever you want in terms of claims in the token. Here's an example of a token trimmed down for length to simply demonstrate what an encoded token may look like. Note the "." dividers.

eyJ0eXAiOF1RSJ9.eyJpc3MiOiJNlcyIsImV4cb3JkIl19.AsYr7vaxFqCztZ_wph_

Here is what that token may look like when decoded from the Base 64 string:

Header

{
  "typ": "JWT",
  "alg": "RS256",
  "x5t": "a3rMUgMFv9tPclLa6yF3zAkfquE",
  "kid": "a3rMUgMFv9tPclLa6yF3zAkfquE"
}

Payload Data

{
  "iss": "https://identity.yourdomain.com/identity",
  "aud": "https://identity.yourdomain.com/identity/resources",
  "exp": 1512842905,
  "nbf": 1512839305,
  "client_id": "apiclient",
  "scope": "openid",
  "sub": "108434458",
  "auth_time": 1512839305,
  "idp": "youridpid",
  "amr": [
    "password"
  ]
}

So what do you need to be worried about with respect to security? Simply this. Make sure whatever you put into your JWT tokens do not reveal secrets or sensitive data that you do not want discovered. Yes, of course, the JWT is signed. The third part of the token is a hash created by the identity server and must be validated on the server side accepting the token when you use it in the Authorization header as a Bearer token.

This means the server side has to have the key used to validate. But on the client side, for unencrypted JWT tokens, the data can be useful. Just don't make it useful to the bad actor. And when you decide to add claims to your JWT from your identity server implementation, be sure you are comfortable with that data being out in the wild.

#3 Authorization Most Common Use

The most common use of a JWT is as a bearer token in the Authorization header as I've just mentioned.

Authorization: Bearer [token]

Here's the flow.

1. Browser (or API client) sends POST to identity endpoint with username and password.
2. Identity server authenticates and creates JWT signed with secret key or certificate.
3. Browser (or API client) receives the JWT token.
4. Browser (or API client) makes request to the app server with Authorization header with "Bearer [token]" in request.
5. App server validates the JWT token and authorizes and executes the request or denies it.
6. Browser (or API client) receives response from the application server.

#4 Getting the "sub" Claim Back from Microsoft's Mapping

Before you spend a lot of time in ASP.NET Core 2 trying to get access to the "sub" (subject) claim in the controller's User (cast as ClaimsPrincipal), just know that it's not your fault. It's Microsoft's. They map claims and are not 100% compliant with the OpenID standard in that the "sub" claim disappears. Here's how you get it back:

public void ConfigureServices(IServiceCollection services)
{
  //config services like logging, Mvc, etc.
  
  JwtSecurityTokenHandler.DefaultInboundClaimTypeMap.Remove("sub"); 
  
  //config services.AddAuthentication and AddAuthorization
}

By removing the "sub" claim from their claim type map, it will reappear in your ClaimsPrincipal like this dummy code written simply to show how to grab the "sub" claim now that it's back.

[HttpGet("{id}"), Authorize("openid")]
public string Get(int id)
{
  var user = User as ClaimsPrincipal;
  var memId = user.Claims
      .Where(x => x.Type == "sub")
      .Select(x => x.Value).FirstOrDefault();
  return memId;
}

Try that without removing it from the type map and you'll get a big fat null.

#5 JWT Tokens Can and Should Expire

If you are using JWT and OpenID, you should make sure that your identity server sets an expiration on the token. And if your authentication request provides your with a refresh token, you should learn how in the client to refresh (call the identity server with the refresh token) your access JWT token. See auth0's details on using refresh tokens.

A refresh token is especially useful for keeping a user logged in without asking her or him to enter a username and password again. And it is a great way to avoid storing credentials locally. Yeah, don't do that.

Conclusion

If you're not using JWT or have not yet become comfortable with tokens, you owe it to yourself to do a little reading, even if you're not a coder. But if you're a coder, you definitely need to grok JWT.