Often you need to write to the logs additional information that can clarify the situation and further simplify the 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.
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 must write to the log information about the error.
There are no problems with logging the exception itself. We can catch it in our controller's action method:
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 we can create a specialized attribute for this:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(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] public async 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.
Doing this for the request body is not difficult:
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 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 message list (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 texts of the SQL queries 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:
public static async 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?
The AsyncLocal<T> class comes to our rescue. 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 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(); } }
The CreateNewErrorContext method immediately creates a new message list and saves it in the CurrentErrorContext field, which has the AsyncLocal type. You can access the current list anywhere in the code with the static Current property. The AttachMessage method adds a new message to the list. It stores messages in an instance of ConcurrentBag , since this method can be called simultaneously from multiple threads. The GetMessages method returns all saved messages, so that they can be written to the log.
Now you can easily initialize and use the ErrorContext inside the 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); } } }
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 request processing takes less time, then everything is in order. I will not write anything to the log in this case. But if time is running out, 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 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. The SetCurrentTimer method creates 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 SetCurrentTimer method, a new timer is created and put into the CurrentTimer variable of the CurrentTimer type. 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 Current property gives 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 of the ConcurrentQueue , since their ordering may be important.
The Message property returns messages collected from a single from the current and all 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 Log method writes information stored in the timer to the log, regardless of whether the runtime threshold has been set or not. At the same time, the Dispose method writes information to the log only if the specified run-time threshold has been exceeded.
Now you can create another attribute for our controller methods:
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 on action methods like this:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async 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 instances of the AsyncLocal class.
I hope the article’s material will be useful for improving the logging system in your applications.