Gathering context information for logging

When you write messages to your logs, sometimes it may be useful to add context information. For example, if you write information about some error, you could also include input data in some form, to be able to reproduce the problem easily. Here I'll show how to gather this additional information.

Setup

First, let's describe the problem we want to solve. I have an ASP.NET MVC Web service. The service accepts POST-requests containing JSON descriptions. After analyzing such description, the service constructs and executes several SQL queries to a database. Then it combines results and returns them to the client.

It is necessary to say that our service heavily uses asynchronous API through async/await and tasks.

Now we have an understanding of the stage. Let's go to the problems.

Gathering context of errors

Sometimes our service fails. The reasons can be different: error in the input JSON, bugs in our code, problems with the database, ... In this case, we need to log information about an error.

There is no problem with an exception itself. We can catch it in the action method of our service:

public class ServiceController : ApiController
{
    [Route("api/service")]
    [HttpPost]
    public async Task<HttpResponseMessage> ServiceAction(
        [FromBody] RequestModel requestModel
    )
    {
        try
        {
            ...
        }
        catch (Exception ex)
        {
            Logger.LogError(ex);
            throw;
        }
    }
}

Or you can create a custom action filter attribute:

public class LogErrorAttribute : ActionFilterAttribute
{
    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        if (actionExecutedContext.Exception != null)
        {
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

and use it with your action method:

[Route("api/service")]
[HttpPost]
[LogError]
public async Task<HttpResponseMessage> ServiceAction(
    [FromBody] RequestModel requestModel
)
{
    ...
}

But we need more. For every error I'd like to have the following additional information:

• JSON of the request.
• Texts of all generated SQL queries.

And there is one more requirement. This information should be written to the log only if an error happened. Otherwise, I don't need it there.

Well, it is not very hard to do it with the JSON from the request:

public class ServiceController : ApiController
{
    [Route("api/service")]
    [HttpPost]
    public async Task<HttpResponseMessage> ServiceAction(
        [FromBody] RequestModel requestModel
    )
    {
        var requestText = await Request.Content.ReadAsStringAsync();

        try
        {
            ...
        }
        catch (Exception ex)
        {
            Logger.LogError(ex);
            Logger.LogError($"Request test is {requestText}");
            throw;
        }
    }
}

But it is not so simple with texts of SQL queries. Let me explain this. These queries are not generated in our action method. They are not even generated in the class of our controller. There can be many and many calls of different methods of different classes before we reach this code. So, how can we extract these texts?

One variant is to use some list of messages (e.g. List<string>). We will create it in our action method (ServiceAction) and pass it down to the method, where SQL queries are generated. There we'll add texts of queries to this list. In this case, if an error happened, in the action method we'll have the list of messages we need to log.

This approach has very serious drawback from my point of view. We have to pass the list of messages through all the chain of calls of different methods until we reach the method, where we generate SQL queries. It means, that many methods will accept it as a parameter only to pass it down. It complicates the code, and I'd try to avoid it.

If you use a DI container and can create your classes from the container, you can inject the list of messages into the controller class and into classes creating SQL queries. Just register the list of messages with 'per request' lifecycle.

But there is a way even if your code does not use a DI container. It would be great if I could access the list of messages through a static property:

public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd)
{
        var message = $"SQL Server query is: {cmd.CommandText}";
        ErrorContext.Current.AttachMessage(message);

        ...
}

There is one serious problem here. Our service can serve several requests simultaneously. And each request must have its own list of messages. Furthermore, while processing a single request, our code can start multiple separate threads (e.g. by async/await). And all these threads must have access to the same instance of the list of messages. How can we implement it?

It can be achieved using an instance of AsyncLocal<T> class. This class guarantees that if you give it some value in one thread this values can be obtained in this thread and in all threads created from this thread from this moment on. At the same time, all other threads will not see this value.

Let's take a look at the complete implementation of the ErrorContext class:

public class ErrorContext
{
    private static readonly object Lock = new object();
    private static readonly AsyncLocal<ErrorContext> CurrentErrorContext = new AsyncLocal<ErrorContext>();

    private readonly Lazy<ConcurrentBag<string>> _attachedMessages = new Lazy<ConcurrentBag<string>>(() => new ConcurrentBag<string>());

    private ErrorContext()
    {}

    public static ErrorContext Current
    {
        get
        {
            lock (Lock)
            {
                var errorContext = CurrentErrorContext.Value;
                if (errorContext == null)
                {
                    CurrentErrorContext.Value = errorContext = new ErrorContext();
                }
                return errorContext;
            }
        }
    }

    public static ErrorContext CreateNewErrorContext()
    {
        lock (Lock)
        {
            var errorContext = new ErrorContext();
            CurrentErrorContext.Value = errorContext;
            return errorContext;
        }
    }

    public void AttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Add(message);
        }
    }

    public IReadOnlyList<string> GetMessages()
    {
        return _attachedMessages.Value.ToArray();
    }

}

Here is how it works. Method CreateNewErrorContext immediately creates a new list of messages and stores it in the CurrentErrorContext field, implemented with AsyncLocal<T>. You can get access to the list in any place of code using static Current property. Method AttachMessage puts a new message on the list. It stores messages inside ConcurrentBag instance, as this method can be simultaneously called from several threads. Method GetMessages returns all stored messages so you can log them.

Now it is easy to initialize and use ErrorContext inside your LogErrorAttribute:

public class LogErrorAttribute : ActionFilterAttribute
{
    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        ErrorContext.CreateNewErrorContext();

        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        if (actionExecutedContext.Exception != null)
        {
            foreach(var message in ErrorContext.Current.GetMessages())
            {
                  Logger.LogError(message);
            }
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

In any place of your code you can add messages to the current error context like this:

ErrorContext.Current.AttachMessage(message);

Logging performance issues

Sometimes my service answers slowly. Not for all requests, but for some of them it takes too long to get a response. I'd like to log information about such requests to be able to deal with them later. How should it be implemented and what information do I need in this case?

First of all, I'd like to set some sort of threshold on work time. If my service takes less time to respond it is Ok. I'll log nothing in this case. But if it takes more time then I must log some information.

What information do I need? Well, I certainly need to know how long it took to process the whole request. But it is not enough. My service does many things: validates the request, gets data from external services, constructs SQL queries, executes these queries, ... I may want to know how long it took to execute each of these parts to understand the root of the problem.

Also, I'll need the same information as for errors. I'll need request body to be able to reproduce the problem. I'll need texts of SQL queries in case they are the slowest part.

How can we do it? With help of the same AsyncLocal class:

public class Timer : IDisposable
{
    private static readonly object Lock = new object();
    private static readonly AsyncLocal<Timer> CurrentTimer = new AsyncLocal<Timer>();

    private readonly Stopwatch _stopwatch = new Stopwatch();
    private readonly Lazy<ConcurrentQueue<Timer>> _attachedTimers = new Lazy<ConcurrentQueue<Timer>>(() => new ConcurrentQueue<Timer>());
    private readonly Lazy<ConcurrentQueue<string>> _attachedMessages = new Lazy<ConcurrentQueue<string>>(() => new ConcurrentQueue<string>());
    private readonly string _description;
    private readonly TimeSpan? _threshold;
    private readonly Timer _previousCurrent;

    private bool _isDisposed;
    private bool _suspendLogging;

    private Timer(Timer previousCurrent, string description = null, TimeSpan? threshold = null)
    {
        _previousCurrent = previousCurrent;
        _description = description;
        _threshold = threshold;
        _stopwatch.Start();
    }

    public static Timer Current
    {
        get
        {
            lock (Lock)
            {
                var timer = CurrentTimer.Value;
                if (timer == null)
                {
                    CurrentTimer.Value = timer = new Timer(null);
                }
                return timer;
            }
        }
    }

    public static Timer SetCurrentTimer(string description, TimeSpan? threshold = null)
    {
        lock (Lock)
        {
            var currentTimer = CurrentTimer.Value;

            var timer = new Timer(currentTimer, description, threshold);

            CurrentTimer.Value = timer;

            currentTimer?._attachedTimers.Value.Enqueue(timer);

            return timer;
        }
    }

    public void AttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Enqueue(message);
        }
    }

    public void Dispose()
    {
        if (!_isDisposed)
        {
            _isDisposed = true;

            _stopwatch.Stop();

            if (_attachedTimers.IsValueCreated)
            {
                foreach (var attachedTimer in _attachedTimers.Value)
                {
                    attachedTimer.Dispose();
                }
            }

            if (!_suspendLogging && _threshold.HasValue && _stopwatch.Elapsed > _threshold.Value)
            {
                Log();
            }

            if (_previousCurrent != null)
            {
                CurrentTimer.Value = _previousCurrent;
            }
        }
    }

    private JObject Message
    {
        get
        {
            Dispose();

            var message = new StringBuilder($"It took {_stopwatch.ElapsedMilliseconds} ms to execute {_description}.");

            if (_threshold.HasValue)
            {
                message.Append($" Duration threshold is {_threshold.Value.TotalMilliseconds} ms.");
            }

            var messageObj = new JObject
            {
                ["message"] = message.ToString(),
            };

            if (_attachedTimers.IsValueCreated && _attachedTimers.Value.Any())
            {
                messageObj["attachedTimers"] = new JArray(_attachedTimers.Value.Select(t => t.Message));
            }

            if (_attachedMessages.IsValueCreated && _attachedMessages.Value.Any())
            {
                messageObj["attachedMessages"] = new JArray(_attachedMessages.Value);
            }

            return messageObj;
        }
    }

    public void Log()
    {
        try
        {
            _suspendLogging = true;

            Dispose();

            if (_stopwatch.Elapsed < _threshold)
            {
                Logger.LogDebug(Message.ToString());
            }
            else
            {
                Logger.LogWarning(Message.ToString());
            }
        }
        finally
        {
            _suspendLogging = false;
        }
    }
}

Let's see how it works. Method SetCurrentTimer creates a new timer. Here you set its description and an optional threshold of duration. Sometimes I want part of my code to execute within some time interval. E.g. I may want to get the response to my request within 3 seconds. In another case, I don't have any particular limitations. E.g. I don't care how long it takes to execute SQL queries, as long as the whole processing of a request takes less than 3 seconds. This is why for some timers you may want to set the threshold, while for others you may don't want to set it.

Inside this method, I create a new timer and assign it to the AsyncLocal variable CurrentTimer. But this is not the whole story. At this moment there can be another active timer. In this case, I attach the new timer to the old one. It allows me to create nested timers. In this case, I'll be able to measure the time of the whole block of code, as well as its parts:

using (Timer.SetCurrentTimer("The whole block"))
{
    ...

    using (Timer.SetCurrentTimer("Part 1"))
    {
        ... 
    }

    ...

    using (Timer.SetCurrentTimer("Part 2"))
    {
        ... 
    }

    ...
}

Property Current gives access to the current timer. It is useful if we want to attach some messages to the timer:

var message = $"SQL Server query is: {cmd.CommandText}";
Timer.Current.AttachMessage(message);

In this case, I store attached messages and nested timers using ConcurrentQueue instances because the order of timers and messages may be important.

Property Message returns combined messages from the current timer and all nested timers. To store these messages in a structured format I use JSON by means of JSON.NET. But it is really not important. You may use any format.

Method Log will write timer information to a log regardless if it has threshold or not. At the same time, Dispose method will write information to a log only if the threshold is set and it was exceeded.

Now we can create another action filter attribute for action methods of our controllers:

public class TimerContextAttribute : ActionFilterAttribute
{
    private readonly string _timerDescription;
    private readonly int _durationThresholdMs;
    private readonly AsyncLocal<Timer> _timer = new AsyncLocal<Timer>();

    public TimerContextAttribute(string timerDescription, int durationThresholdMs)
    {
        if (string.IsNullOrWhiteSpace(timerDescription)) throw new ArgumentNullException(nameof(timerDescription));
        _timerDescription = timerDescription;
        _durationThresholdMs = durationThresholdMs;
    }

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        _timer.Value = Timer.SetCurrentTimer(_timerDescription,
            TimeSpan.FromMilliseconds(_durationThresholdMs));

        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        _timer.Value?.Dispose();

    }
}

and use it for our actions:

[Route("api/service")]
[HttpPost]
[TimerContext("For ServiceAction method", 3000)]
public async Task<HttpResponseMessage> ServiceAction(
    [FromBody] RequestModel requestModel
)
{
    ...
}

Conclusion

In this article, I described how you can easily collect information from many places in your code and retrieve it later. It can be done using static properties and methods, which give access to instances of AsyncLocal class.

I hope this information could be useful and allow you to improve logging in your applications.