MVC logging scope

Question

I read that inside MVC middleware framework use logging scope withing contoller's action:

Use Scopes sparingly, and only for actions with a bounded start and end. For example, the framework provides a scope around MVC actions. Avoid nesting many scopes within one another.

And

A scope is an IDisposable type returned by calling the ILogger.BeginScope method, which lasts from the moment it is created until it is disposed. Any logging state, such as a transaction id, is attached to the scope when it is created.

I'm trying to use this feature to write some log information. I executed steps below:

1) create Asp.net core MVC app
2) set property "IncludeScopes" as "true" in appsetting.json
3) create controller and action like this:

  [Route("api/[controller]")]
public class TodoController : Controller
{
    private readonly ILogger<TodoController> _logger;
    public TodoController(ILogger<TodoController> logger)
    {
        _logger = logger;
    }

    // GET: api/values
    [HttpGet]
    public IEnumerable<string> Get()
    {
        _logger.LogInformation(1000, "Listing all items started");
        Thread.Sleep(2000);
        _logger.LogInformation(1000, "Listing all items finished");
        return new string[] { "value1", "value2" };
    }
}

I expect that my log messages flow always will contains only "Listing all items started" and "Listing all items finished" parts which not separated by each other. But when I started two requests in the same time a got log flow as:

RequestId: xxx Listing all items started
RequestId: yyy Listing all items started
RequestId: xxx Listing all items finished
RequestId: yyy Listing all items finished

What's the reason? Is it correct behaviour and I misunderstood "scope" term in context of logging?

Answer 1

Logging scopes help to create scopes by which any log statements created within it would have that information available.

Following out is from ConsoleLogger with IncludeScopes set to true:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      => RequestId:0HKT6JC0EVFNA RequestPath:/api/values
      Request starting HTTP/1.1 GET http://localhost:5000/api/values
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
      => RequestId:0HKT6JC0EVFNA RequestPath:/api/values => WebApplication8.Controllers.ValuesController.Get (WebApplication8)
      Executing action method WebApplication8.Controllers.ValuesController.Get (WebApplication8) with arguments () - ModelState is Valid
info: Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor[1]
      => RequestId:0HKT6JC0EVFNA RequestPath:/api/values => WebApplication8.Controllers.ValuesController.Get (WebApplication8)
      Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
      => RequestId:0HKT6JC0EVFNA RequestPath:/api/values => WebApplication8.Controllers.ValuesController.Get (WebApplication8)
      Executed action WebApplication8.Controllers.ValuesController.Get (WebApplication8) in 322.8533ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
      => RequestId:0HKT6JC0EVFNA RequestPath:/api/values
      Request finished in 428.477ms 200 application/json; charset=utf-8

If you notice the above log, here RequestId:0HKT6JC0EVFNA is being printed for every log statement (as mentioned earlier all log statements within a scope or nested scope would get information from all those scopes)

Some log scopes that are created by default in ASP.NET are the RequestId scope as seen above and also scope around MVC's controller action invocation as seen from the log(example this line: => WebApplication8.Controllers.ValuesController.Get (WebApplication8))

You can yourself creates scopes too if you need:

using (logger.BeginScope("OrderOrchestrationId:{OrderOrchestrationId}", orderOrchestrationId))
{
   // any log statements from here on would have `OrderOrchestrationId` available
}

Note: All loggers do not support scopes by default. In case of ConsoleLogger it prints out scopes in text format but scopes really shine in case of structured logging as discussed next.

How are scopes useful? ASP.NET logging framework allows you to do structured logging. For example, in the above code {OrderOrchestrationId} was used for this purpose. Serilog has a logger for ASP.NET 5 which implements structured logging and using this you can for example write data as json data to Azure's DocumentDB. So in this case if OrderOrchestrationId was written to Azure's DocumentDB, you can search the logs with this id which would have been difficult to do with flat text file searching.