收集日志记录的上下文信息

安装

首先，让我们描述我们要解决的问题。我有一个 ASP.NET MVC Web 服务。该服务接受包含 JSON 描述的 POST 请求。在分析完此类描述后，该服务会构造并执行多个 SQL 查询到数据库。然后它组合结果并将它们返回给客户端。

需要说明的是，我们的服务大量使用通过 async/await 和任务实现的异步 API。

现在我们已经对阶段有了一个了解。让我们来谈谈问题。

收集错误的上下文

有时我们的服务会失败。原因可能不同：输入 JSON 错误、我们代码中的 bug、数据库问题……在这种情况下，我们需要记录有关错误的详细信息。

异常本身没有问题。我们可以在服务的操作方法中捕获它

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

或者您可以创建一个自定义操作过滤器属性

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

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

并将其与您的操作方法一起使用

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

但我们需要更多。对于每个错误，我希望有以下额外信息

• 请求的 JSON
• 所有生成的 SQL 查询的文本

还有一项要求。这些信息只有在发生错误时才应写入日志。否则，我不需要它在那里。

好吧，用请求中的 JSON 来做这件事并不难

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;
        }
    }
}

但 SQL 查询的文本并非如此简单。让我解释一下。这些查询不是在我们的操作方法中生成的。它们甚至不是在我们的控制器类中生成的。在到达这段代码之前，可能会有许多不同类别的许多调用。那么，我们如何提取这些文本呢？

一个方法是使用消息列表（例如，List<string>）。我们将在操作方法（ServiceAction）中创建一个列表，并将其传递给生成 SQL 查询的方法。在那里，我们将查询文本添加到此列表中。在这种情况下，如果发生错误，在操作方法中，我们将获得需要记录的消息列表。

从我的角度来看，这种方法有一个非常严重的缺点。我们必须将消息列表通过所有不同方法的调用链传递，直到我们到达生成 SQL 查询的方法。这意味着许多方法将仅作为参数来传递它。这会使代码复杂化，我将尝试避免它。

如果您使用 DI 容器并且可以从容器创建类，您可以将消息列表注入到控制器类和创建 SQL 查询的类中。只需使用“每个请求”生命周期注册消息列表。

但即使您的代码不使用 DI 容器，也有办法做到。如果我可以通过一个 static 属性访问消息列表，那就太好了

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

        ...
}

这里有一个严重的问题。我们的服务可以同时处理多个请求。每个请求都必须有自己的消息列表。此外，在处理单个请求时，我们的代码可以启动多个独立的线程（例如，通过 async/await）。所有这些线程都必须能够访问同一实例的消息列表。我们如何实现这一点？

可以使用 AsyncLocal<T> 类的实例来实现。此类保证，如果您在一个线程中给它一个值，则可以在此线程以及从该线程开始创建的所有线程中获取该值。同时，所有其他线程将看不到此值。

让我们看一下 ErrorContext 类的完整实现

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();
    }

}

它的工作原理是这样的。CreateNewErrorContext 方法立即创建一个新的消息列表并将其存储在 CurrentErrorContext 字段中，该字段使用 AsyncLocal<T> 实现。您可以使用 static Current 属性在任何代码位置访问该列表。AttachMessage 方法将新消息添加到列表中。它将消息存储在 ConcurrentBag 实例内，因为此方法可以从多个线程同时调用。GetMessages 方法返回所有存储的消息，以便您可以记录它们。

现在，在您的 LogErrorAttribute 中初始化和使用 ErrorContext 非常容易

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);
        }
    }
}

在您的任何代码位置，您可以像这样向当前错误上下文添加消息

ErrorContext.Current.AttachMessage(message);

记录性能问题

有时，我的服务响应缓慢。并非所有请求都如此，但有些请求需要太长时间才能获得响应。我想记录有关这些请求的信息，以便以后能够处理它们。应该如何实现，在这种情况下我需要什么信息？

首先，我想设置某种工作时间阈值。如果我的服务响应时间较短，那就没问题。在这种情况下，我将不记录任何内容。但如果花费的时间更长，那么我必须记录一些信息。

我需要什么信息？嗯，我当然需要知道处理整个请求花了多长时间。但这还不够。我的服务做了很多事情：验证请求、从外部服务获取数据、构造 SQL 查询、执行这些查询……我可能想知道执行这些部分中的每一个需要多长时间，以了解问题的根源。

此外，我还需要与错误相同的信息。我需要请求体，以便能够重现问题。我需要 SQL 查询的文本，以防它们是最慢的部分。

我们如何做到这一点？借助相同的 AsyncLocal 类

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;
        }
    }
}

让我们看看它是如何工作的。SetCurrentTimer 方法创建一个新计时器。在这里，您设置其描述和可选的持续时间阈值。有时，我希望我的部分代码在某个时间间隔内执行。例如，我可能希望在 3 秒内获得对我的请求的响应。在另一种情况下，我没有任何特别的限制。例如，我不在乎执行 SQL 查询需要多长时间，只要处理整个请求的时间少于 3 秒即可。这就是为什么对于某些计时器，您可能希望设置阈值，而对于其他计时器，您可能不希望设置它。

在此方法中，我创建一个新计时器并将其分配给 AsyncLocal 变量 CurrentTimer。但这并非全部。此时，可能还有另一个活动计时器。在这种情况下，我会将新计时器附加到旧计时器。这允许我创建嵌套计时器。在这种情况下，我将能够测量整个代码块的时间以及它的各个部分的时间

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

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

    ...

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

    ...
}

Current 属性可以访问当前计时器。如果我们想向计时器附加一些消息，这很有用

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

在这种情况下，我使用 ConcurrentQueue 实例存储附加的消息和嵌套计时器，因为计时器和消息的顺序可能很重要。

Message 属性返回当前计时器和所有嵌套计时器的组合消息。为了以结构化格式存储这些消息，我通过 JSON.NET 使用 JSON。但这真的不重要。您可以使用任何格式。

Log 方法将记录计时器信息，无论它是否有阈值。同时，Dispose 方法仅在设置了阈值且超过阈值时才将信息写入日志。

现在我们可以为我们的控制器的操作方法创建另一个操作过滤器属性

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();
    }
}

并将其用于我们的操作

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

结论

在本文中，我描述了如何轻松地从代码中的许多地方收集信息并在以后检索它。这可以通过使用 static 属性和方法来实现，这些属性和方法提供了对 AsyncLocal 类实例的访问。

希望这些信息能有所帮助，并能让您改进应用程序中的日志记录。

您可以在 我的博客 上阅读我更多的文章。