Gathering contextual information for logging

Original author: Ivan Iakimov
  • Transfer

Often, you need to write to the logs additional information that can clarify the situation and further simplify debugging of the application. For example, if error information is logged, it would be nice to also save input data in some form, to make it easier to reproduce the problem. Here I want to describe an approach that allows you to collect this additional information.


Formulation of the problem


Let we have ASP.NET MVC We-service. It accepts POST requests containing a description of what needs to be done in JSON format. After analyzing such a description, the service creates and executes several SQL queries to the database. It then combines the results and sends them to the client.


It must be said that this service makes extensive use of asynchrony and multithreading via async / await and Task.


Now, when we understand what we are dealing with, let's move on to problems.


Gathering contextual information about errors


Sometimes our service gives errors. The reasons may be different: incorrect JSON at the entrance, bugs in the code, problems with the database, ... In this case, we should write to the log information about the error.


There are no problems with logging the exception itself. We can catch it in the action method of our controller:


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

Or we can create a specialized attribute for this:


publicclassLogErrorAttribute : ActionFilterAttribute
{
    publicoverridevoidOnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);
        if (actionExecutedContext.Exception != null)
        {
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

and use it on the action method:


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

But we need more. For each error we want to save additional information:


  • JSON body of the request body.
  • The text of all generated SQL queries.

There is one more requirement. This additional information should be recorded in the log only in case of an error. Otherwise, we do not need it in the logs.


To do this for the request body is not difficult:


publicclassServiceController : ApiController
{
    [Route("api/service")]
    [HttpPost]
    publicasync 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 for SQL queries, things are not so simple. The fact is that these requests are not generated by an action method. They are not even generated in the controller. Between the action method and the method that generates SQL, there are many calls to other methods of other classes. How can we extract the texts of these requests when we need them?


One option is to use a list of messages (for example, List<string>). We create it in our action method ( ServiceAction) and pass it to the method that generates SQL. There we will add the SQL query texts to this list. In case of an error, the action method will have a list of messages to be placed in the log.


This method has a very significant, in my opinion, disadvantage. We will have to pass our list of messages along the entire chain of method calls until we reach the method that generates the SQL. This means that in many places this list of messages will be needed only to pass it on. This complicates the code, and I would try to avoid it.


If you are using a DI container and can create your classes from it, then you can try to put a list of messages in a container with a “per request” lifetime. The class that generates SQL will accept this message list as a constructor parameter. Then both the instance of this class and the controller instance will be able to access the same instance of the message list.


But there is a more convenient way to collect contextual information, even if you are not using a DI container. It would be nice if we could access the list of messages through a static property:


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

There is a serious problem here. Our service can simultaneously serve multiple requests. And each such request must have its own list of messages. Moreover, when processing a single request, our code can spawn multiple threads (for example, using async / await ). And all these threads must have access to the same list of messages. How can this be implemented?


We come to the aid of the class AsyncLocal<T>. It guarantees that if you put some value in an instance of this class in one thread, then you can get this value in this thread, as well as in all threads running from this starting from now on. At the same time, all other threads will not have access to this value.


Let's look at the implementation of the class ErrorContext:


publicclassErrorContext
{
    privatestaticreadonlyobject Lock = newobject();
    privatestaticreadonly AsyncLocal<ErrorContext> CurrentErrorContext = new AsyncLocal<ErrorContext>();
    privatereadonly Lazy<ConcurrentBag<string>> _attachedMessages = new Lazy<ConcurrentBag<string>>(() => new ConcurrentBag<string>());
    privateErrorContext()
    {}
    publicstatic ErrorContext Current
    {
        get
        {
            lock (Lock)
            {
                var errorContext = CurrentErrorContext.Value;
                if (errorContext == null)
                {
                    CurrentErrorContext.Value = errorContext = new ErrorContext();
                }
                return errorContext;
            }
        }
    }
    publicstatic ErrorContext CreateNewErrorContext()
    {
        lock (Lock)
        {
            var errorContext = new ErrorContext();
            CurrentErrorContext.Value = errorContext;
            return errorContext;
        }
    }
    publicvoidAttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Add(message);
        }
    }
    public IReadOnlyList<string> GetMessages()
    {
        return _attachedMessages.Value.ToArray();
    }
}

The method CreateNewErrorContextimmediately creates a new list of messages and saves it in a field of CurrentErrorContexttype AsyncLocal. You can access the current list anywhere in the code using a static property Current. The method AttachMessageadds a new message to the list. It stores messages in an instance ConcurrentBag, since this method can be called simultaneously from multiple threads. The method GetMessagesreturns all saved messages, so that they can be written to the log.


Now you can easily initialize and use ErrorContextinside LogErrorAttribute:


publicclassLogErrorAttribute : ActionFilterAttribute
{
    publicoverridevoidOnActionExecuting(HttpActionContext actionContext)
    {
        ErrorContext.CreateNewErrorContext();
        base.OnActionExecuting(actionContext);
    }
    publicoverridevoidOnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);
        if (actionExecutedContext.Exception != null)
        {
            foreach(var message in ErrorContext.Current.GetMessages())
            {
                  Logger.LogError(message);
            }
            Logger.LogError(actionExecutedContext.Exception);
        }
    }
}

Anywhere in your code, you can add your message to the current error context as follows:


ErrorContext.Current.AttachMessage(message);

Performance issues logging


Sometimes my service is slow. Not for all requests, but for some execution takes too much time. I would like to save information about such requests in order to analyze it later. How can this be implemented, and what information do we need?


First of all, I need some runtime threshold. If the processing of the request takes less time, then everything is in order. I will not write anything to the log in this case. But if more time is spent, I have to add some information to the log.


What information do I need? Definitely need to know how long it took to process the request. But this is not enough. My service does a lot of things: checking query parameters, getting data from other services, building SQL queries and executing them ... I need to know how long each such part took to understand where the problem is hidden.


In addition, I need the same information as for errors. I need a request body to be able to reproduce the problem. I need SQL query texts in case they take the most time.


How can this be achieved? Again, using the class AsyncLocal:


publicclassTimer : IDisposable
{
    privatestaticreadonlyobject Lock = newobject();
    privatestaticreadonly AsyncLocal<Timer> CurrentTimer = new AsyncLocal<Timer>();
    privatereadonly Stopwatch _stopwatch = new Stopwatch();
    privatereadonly Lazy<ConcurrentQueue<Timer>> _attachedTimers = new Lazy<ConcurrentQueue<Timer>>(() => new ConcurrentQueue<Timer>());
    privatereadonly Lazy<ConcurrentQueue<string>> _attachedMessages = new Lazy<ConcurrentQueue<string>>(() => new ConcurrentQueue<string>());
    privatereadonlystring _description;
    privatereadonly TimeSpan? _threshold;
    privatereadonly Timer _previousCurrent;
    privatebool _isDisposed;
    privatebool _suspendLogging;
    privateTimer(Timer previousCurrent, string description = null, TimeSpan? threshold = null)
    {
        _previousCurrent = previousCurrent;
        _description = description;
        _threshold = threshold;
        _stopwatch.Start();
    }
    publicstatic Timer Current
    {
        get
        {
            lock (Lock)
            {
                var timer = CurrentTimer.Value;
                if (timer == null)
                {
                    CurrentTimer.Value = timer = new Timer(null);
                }
                return timer;
            }
        }
    }
    publicstatic 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;
        }
    }
    publicvoidAttachMessage(string message)
    {
        if (!string.IsNullOrWhiteSpace(message))
        {
            _attachedMessages.Value.Enqueue(message);
        }
    }
    publicvoidDispose()
    {
        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;
        }
    }
    publicvoidLog()
    {
        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. The method SetCurrentTimercreates a new timer. Here you can set its description and optional runtime threshold.


Why is this threshold not required? Sometimes I need a part of my code to run no longer than a certain time. So I can wish that the entire request to the service was processed in 3 seconds. In other cases, I do not want to impose restrictions on the execution time. For example, it does not matter to me how long it takes to execute my SQL queries, as long as the entire request to the service is processed in less than 3 seconds. For this reason, for some timers, you need to set a runtime threshold, while for others it is not.


Inside the method SetCurrentTimer, a new timer is created and put into a CurrentTimertype variable AsyncLocal. But that is not all. At this point, another active timer may already exist. In this case, the newly created timer joins the existing one. This allows you to create nested timers to measure the execution time of both the entire code block and its parts:


using (Timer.SetCurrentTimer("The whole block"))
{
    ...
    using (Timer.SetCurrentTimer("Part 1"))
    {
        ... 
    }
    ...
    using (Timer.SetCurrentTimer("Part 2"))
    {
        ... 
    }
    ...
}

The property Currentgives access to the current timer. This is useful if you want to add some messages to it:


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

Here, the attached messages and nested timers are stored in instances ConcurrentQueue, since their ordering may be important.


The property Messagereturns collected in a single message from the current and all the timers put into it. Here I use JSON classes from the JSON.NET library to structure all messages. But in fact it is not so important. You can use any format.


The method Logwrites information stored in the timer to the log, regardless of whether the runtime threshold has been set or not. At the same time, the method Disposewrites information to the log only if the specified run-time threshold has been exceeded.


Now you can create another attribute for our controller methods:


publicclassTimerContextAttribute : ActionFilterAttribute
{
    privatereadonlystring _timerDescription;
    privatereadonlyint _durationThresholdMs;
    privatereadonly AsyncLocal<Timer> _timer = new AsyncLocal<Timer>();
    publicTimerContextAttribute(string timerDescription, int durationThresholdMs)
    {
        if (string.IsNullOrWhiteSpace(timerDescription)) thrownew ArgumentNullException(nameof(timerDescription));
        _timerDescription = timerDescription;
        _durationThresholdMs = durationThresholdMs;
    }
    publicoverridevoidOnActionExecuting(HttpActionContext actionContext)
    {
        _timer.Value = Timer.SetCurrentTimer(_timerDescription,
            TimeSpan.FromMilliseconds(_durationThresholdMs));
        base.OnActionExecuting(actionContext);
    }
    publicoverridevoidOnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);
        _timer.Value?.Dispose();
    }
}

and use it on action methods like this:


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

Conclusion


In this article, I described how to simply collect information from many places in the code and access it later. Such functionality can be implemented using static properties and methods that manipulate class instances AsyncLocal.


I hope the article material will be useful for improving the logging system in your applications.


Also popular now: