通常，您需要在日志中写入其他信息，以澄清情况并进一步简化应用程序的调试。 例如，如果记录了错误信息，最好也以某种形式保存输入数据，以便更轻松地重现问题。 在这里，我想描述一种允许您收集这些附加信息的方法。
问题陈述
假设我们有一个ASP.NET MVC We服务。 它接受POST请求，其中包含需要以JSON格式进行描述的内容。 在分析了这样的描述之后，该服务将创建并执行几个对数据库的SQL查询。 然后，他合并结果并将其发送给客户端。
必须说，该服务通过async / await和Task广泛使用了异步和多线程。
现在我们了解了我们要处理的内容，让我们继续解决问题。
有时我们的服务会出错。 原因可能不同：错误的JSON输入，代码中的错误，数据库问题...在这种情况下，我们应该将错误信息写入日志。
记录异常本身没有问题。 我们可以在控制器的action方法中捕获它：
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); } } }
并在action方法上使用它：
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
但是我们还需要更多。 对于每个错误，我们要存储其他信息：
- 请求的JSON正文的文本。
- 所有生成的SQL查询的文本。
还有另一项要求。 仅在发生错误时，才应在日志中记录此附加信息。 否则，我们在日志中不需要它。
为请求主体执行此操作并不困难：
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查询，一切并不是那么简单。 事实是这些请求不是由action方法生成的。 它们甚至不在控制器中生成。 在action方法和生成SQL的方法之间，有许多对其他类的其他方法的调用。 在需要时如何提取这些请求的文本？
一种选择是使用消息列表（例如List<string> ）。 我们在操作方法（ ServiceAction ）中创建它，并将其传递给生成SQL的方法。 在那里，我们将SQL查询文本添加到此列表中。 万一发生错误，该操作方法将具有需要在日志中放置的消息列表。
在我看来，此方法有一个非常重要的缺点。 我们必须在整个方法调用链中传递消息列表，直到到达生成SQL的方法为止。 这意味着在许多地方，只需要传递此消息列表即可。 这会使代码变得复杂，因此我将尽量避免使用它。
如果使用DI容器并且可以从中创建类，则可以尝试将消息列表以“每个请求”生存期放入容器中。 SQL生成类将接受此消息列表作为构造函数参数。 然后，此类的实例和控制器的实例都将能够访问消息列表的相同实例。
但是，即使您没有使用DI容器，也有一种更方便的方法来收集上下文信息。 如果我们可以通过静态属性访问消息列表，那就太好了：
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方法立即创建一个新的消息列表，并将其保存在AsyncLocal类型的CurrentErrorContext字段中。 您可以使用静态属性Current在代码中的任何位置访问当前列表。 AttachMessage方法将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秒）即可处理整个服务请求无关紧要。 因此，对于某些计时器，需要设置运行时阈值，而对于其他计时器则不需要。
在SetCurrentTimer方法内部，将创建一个新计时器，并将其放入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 ) { ... }
结论
在本文中，我描述了从代码中的许多地方收集信息并在以后访问它是多么简单。 可以使用操纵AsyncLocal类的实例的静态属性和方法来实现这种功能。
我希望本文对改进应用程序中的日志记录系统有用。