Oft müssen Sie zusätzliche Informationen in die Protokolle schreiben, um die Situation zu klären und das Debuggen der Anwendung weiter zu vereinfachen. Wenn beispielsweise Fehlerinformationen protokolliert werden, ist es hilfreich, die Eingabedaten auch in irgendeiner Form zu speichern, damit das Problem leichter reproduziert werden kann. Hier möchte ich einen Ansatz beschreiben, mit dem Sie diese zusätzlichen Informationen sammeln können.
Erklärung des Problems
Angenommen, wir haben einen ASP.NET MVC We-Service. Es akzeptiert POST-Anforderungen, die eine Beschreibung dessen enthalten, was im JSON-Format zu tun ist. Nach der Analyse einer solchen Beschreibung erstellt der Dienst mehrere SQL-Abfragen und führt sie in der Datenbank aus. Anschließend kombiniert er die Ergebnisse und sendet sie an den Kunden.
Es muss gesagt werden, dass dieser Dienst Asynchronität und Multithreading durch Async / Awarit und Task großem Umfang nutzt.
Nachdem wir verstanden haben, womit wir es zu tun haben, gehen wir zu den Problemen über.
Manchmal gibt unser Service Fehler. Die Gründe können unterschiedlich sein: falsche Eingabe-JSON, Fehler im Code, Probleme mit der Datenbank ... In diesem Fall sollten wir Fehlerinformationen in das Protokoll schreiben.
Es gibt kein Problem, die Ausnahme selbst zu protokollieren. Wir können es in der Aktionsmethode unseres Controllers abfangen:
public class ServiceController : ApiController { [Route("api/service")] [HttpPost] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { try { ... } catch (Exception ex) { Logger.LogError(ex); throw; } } }
Oder wir können ein spezielles Attribut dafür erstellen:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { Logger.LogError(actionExecutedContext.Exception); } } }
und verwenden Sie es für die Aktionsmethode:
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Aber wir brauchen mehr. Für jeden Fehler möchten wir zusätzliche Informationen speichern:
- Der Text des JSON-Textes der Anforderung.
- Der Text aller generierten SQL-Abfragen.
Es gibt noch eine Anforderung. Diese zusätzlichen Informationen sollten nur dann im Protokoll aufgezeichnet werden, wenn ein Fehler auftritt. Andernfalls benötigen wir es nicht in den Protokollen.
Dies für den Anfragetext zu tun ist nicht schwierig:
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; } } }
Bei SQL-Abfragen ist jedoch nicht alles so einfach. Tatsache ist, dass diese Anforderungen nicht von der Aktionsmethode generiert werden. Sie werden nicht einmal in der Steuerung generiert. Zwischen der Aktionsmethode und der SQL-Generierungsmethode werden viele Methoden anderer Klassen aufgerufen. Wie extrahieren wir die Texte dieser Anfragen, wenn wir sie brauchen?
Eine Möglichkeit besteht darin, eine Liste von Nachrichten zu verwenden (z. B. List<string> ). Wir erstellen es in unserer Aktionsmethode ( ServiceAction ) und übergeben es an die Methode, die SQL generiert. Dort werden wir die SQL-Abfragetexte zu dieser Liste hinzufügen. Im Falle eines Fehlers enthält die Aktionsmethode eine Liste der Nachrichten, die im Protokoll abgelegt werden müssen.
Diese Methode hat meiner Meinung nach einen sehr bedeutenden Nachteil. Wir müssen unsere Liste der Nachrichten entlang der gesamten Kette von Methodenaufrufen übergeben, bis wir die Methode erreichen, die SQL generiert. Dies bedeutet, dass diese Liste von Nachrichten vielerorts nur zur Weitergabe benötigt wird. Dies kompliziert den Code und ich würde versuchen, ihn zu vermeiden.
Wenn Sie einen DI-Container verwenden und Ihre Klassen daraus erstellen können, können Sie versuchen, die Liste der Nachrichten mit einer Lebensdauer pro Anforderung in den Container einzufügen. Die SQL-Generierungsklasse akzeptiert diese Nachrichtenliste als Konstruktorparameter. Dann können sowohl eine Instanz dieser Klasse als auch eine Instanz des Controllers auf dieselbe Instanz der Nachrichtenliste zugreifen.
Es gibt jedoch eine bequemere Möglichkeit, Kontextinformationen zu erfassen, selbst wenn Sie keinen DI-Container verwenden. Es wäre schön, wenn wir über eine statische Eigenschaft auf die Nachrichtenliste zugreifen könnten:
public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd) { var message = $"SQL Server query is: {cmd.CommandText}"; ErrorContext.Current.AttachMessage(message); ... }
Hier liegt ein ernstes Problem vor. Unser Service kann gleichzeitig mehrere Anfragen bedienen. Und jede solche Anfrage sollte eine eigene Liste von Nachrichten haben. Darüber hinaus kann unser Code bei der Verarbeitung einer einzelnen Anforderung mehrere Threads erzeugen (z. B. mit async / await ). Alle diese Threads müssen Zugriff auf dieselbe Nachrichtenliste haben. Wie kann dies umgesetzt werden?
Die AsyncLocal<T> -Klasse AsyncLocal<T> uns dabei. Es garantiert, dass Sie, wenn Sie einen Wert in eine Instanz dieser Klasse in einem Thread einfügen, diesen Wert in diesem Thread sowie in allen von diesem Thread aus gestarteten Threads ab sofort erhalten können. Gleichzeitig haben alle anderen Threads keinen Zugriff auf diesen Wert.
Schauen wir uns die Implementierung der ErrorContext Klasse an:
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(); } }
Die CreateNewErrorContext Methode erstellt sofort eine neue Nachrichtenliste und speichert sie im Feld CurrentErrorContext , das vom Typ AsyncLocal . Mit der statischen Eigenschaft Current können Sie an einer beliebigen Stelle im Code auf die aktuelle Liste zugreifen. Die AttachMessage Methode fügt der Liste eine neue Nachricht hinzu. Es speichert Nachrichten in einer Instanz von ConcurrentBag , da diese Methode von mehreren Threads gleichzeitig aufgerufen werden kann. Die GetMessages Methode gibt alle gespeicherten Nachrichten zurück, damit sie in das Protokoll geschrieben werden können.
Jetzt können Sie ErrorContext in LogErrorAttribute initialisieren und verwenden:
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); } } }
Überall in Ihrem Code können Sie Ihre Nachricht wie folgt zum aktuellen Fehlerkontext hinzufügen:
ErrorContext.Current.AttachMessage(message);
Leistungsprotokollierung
Manchmal ist mein Service langsam. Nicht für alle Abfragen, aber für einige dauert es zu lange, bis sie abgeschlossen sind. Ich möchte Informationen über solche Anfragen behalten, um sie später zu analysieren. Wie kann dies umgesetzt werden und welche Informationen benötigen wir?
Zunächst brauche ich eine Laufzeitschwelle. Wenn die Bearbeitung der Anfrage weniger Zeit in Anspruch nimmt, ist alles in Ordnung. Ich werde in diesem Fall nichts in das Protokoll schreiben. Wenn es jedoch länger dauert, muss ich dem Protokoll einige Informationen hinzufügen.
Welche Informationen brauche ich? Sie müssen auf jeden Fall wissen, wie lange die Bearbeitung der Anfrage gedauert hat. Das reicht aber nicht. Mein Dienst erledigt viele Dinge: Abfrageparameter überprüfen, Daten von anderen Diensten abrufen, SQL-Abfragen erstellen und ausführen ... Ich muss wissen, wie viel Zeit jeder dieser Teile benötigt hat, um zu verstehen, wo das Problem verborgen ist.
Außerdem benötige ich die gleichen Informationen wie für die Fehler. Ich benötige einen Anfragetext, um das Problem reproduzieren zu können. Ich benötige die Texte von SQL-Abfragen, falls sie am längsten dauern.
Wie kann dies erreicht werden? Verwenden Sie erneut die AsyncLocal Klasse:
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; } } }
Mal sehen, wie es funktioniert. Die SetCurrentTimer Methode erstellt einen neuen Timer. Hier können Sie die Beschreibung und einen optionalen Laufzeitschwellenwert angeben.
Warum ist dieser Schwellenwert optional? Manchmal muss ein Teil meines Codes nicht länger als eine bestimmte Zeit ausgeführt werden. Ich kann mir also wünschen, dass die gesamte Serviceanfrage in 3 Sekunden bearbeitet wird. In anderen Fällen möchte ich die Laufzeit nicht einschränken. Zum Beispiel spielt es für mich keine Rolle, wie lange es dauert, meine SQL-Abfragen auszuführen, bis die gesamte Serviceanforderung in weniger als 3 Sekunden verarbeitet ist. Aus diesem Grund muss für einige Timer ein Laufzeitschwellenwert festgelegt werden, für andere nicht.
Innerhalb der SetCurrentTimer Methode wird ein neuer Timer erstellt und in die CurrentTimer Variable vom Typ AsyncLocal . Das ist aber noch nicht alles. Zu diesem Zeitpunkt ist möglicherweise bereits ein anderer aktiver Timer vorhanden. In diesem Fall wird der gerade erstellte neue Timer mit dem vorhandenen verbunden. Auf diese Weise können Sie verschachtelte Timer erstellen, um die Ausführungszeit des gesamten Codeblocks und seiner Teile zu messen:
using (Timer.SetCurrentTimer("The whole block")) { ... using (Timer.SetCurrentTimer("Part 1")) { ... } ... using (Timer.SetCurrentTimer("Part 2")) { ... } ... }
Die Current Eigenschaft ermöglicht den Zugriff auf den aktuellen Timer. Dies ist nützlich, wenn Sie einige Nachrichten hinzufügen möchten:
var message = $"SQL Server query is: {cmd.CommandText}"; Timer.Current.AttachMessage(message);
Hier werden die angehängten Nachrichten und verschachtelten Timer in Instanzen von ConcurrentQueue gespeichert, da ihre Reihenfolge wichtig sein kann.
Die Message Eigenschaft gibt Nachrichten zurück, die in einer einzelnen Einheit vom aktuellen und allen darin gestapelten Timern gesammelt wurden. Hier verwende ich die JSON-Klassen aus der JSON.NET- Bibliothek, um alle Nachrichten zu strukturieren. Aber eigentlich ist es nicht so wichtig. Sie können ein beliebiges Format verwenden.
Die Log schreibt im Timer gespeicherte Informationen in das Protokoll, unabhängig davon, ob der Laufzeitschwellenwert festgelegt wurde oder nicht. Gleichzeitig schreibt die Dispose Methode nur dann Informationen in das Protokoll, wenn der festgelegte Laufzeitschwellenwert überschritten wurde.
Jetzt können wir ein weiteres Attribut für die Methoden unserer Controller erstellen:
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(); } }
und verwenden Sie es für Aktionsmethoden wie diese:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Fazit
In diesem Artikel habe ich beschrieben, wie einfach es ist, Informationen an vielen Stellen im Code zu sammeln und später darauf zuzugreifen. Solche Funktionen können mithilfe statischer Eigenschaften und Methoden implementiert werden, mit denen Instanzen der AsyncLocal Klasse AsyncLocal .
Ich hoffe, der Artikel wird nützlich sein, um das Protokollierungssystem in Ihren Anwendungen zu verbessern.