Souvent, vous devez écrire des informations supplémentaires dans les journaux, ce qui peut clarifier la situation et simplifier davantage le débogage de l'application. Par exemple, si les informations d'erreur sont enregistrées, il serait bien d'enregistrer également les données d'entrée sous une forme quelconque, afin de reproduire plus facilement le problème. Ici, je veux décrire une approche qui vous permet de collecter ces informations supplémentaires.
Énoncé du problème
Supposons que nous ayons un service ASP.NET MVC We. Il accepte les requêtes POST contenant une description de ce qui doit être fait au format JSON. Après avoir analysé une telle description, le service crée et exécute plusieurs requêtes SQL dans la base de données. Il combine ensuite les résultats et les envoie au client.
Il faut dire que ce service utilise largement l'asynchronie et le multithreading via async / wait et Task .
Maintenant que nous comprenons à quoi nous avons affaire, passons aux problèmes.
Parfois, notre service donne des erreurs. Les raisons peuvent être différentes: entrée JSON incorrecte, bogues dans le code, problèmes avec la base de données ... Dans ce cas, nous devons écrire des informations d'erreur dans le journal.
Il n'y a aucun problème à enregistrer l'exception elle-même. Nous pouvons l'attraper dans la méthode d'action de notre contrôleur:
public class ServiceController : ApiController { [Route("api/service")] [HttpPost] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { try { ... } catch (Exception ex) { Logger.LogError(ex); throw; } } }
Ou nous pouvons créer un attribut spécialisé pour cela:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { Logger.LogError(actionExecutedContext.Exception); } } }
et l'utiliser sur la méthode d'action:
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Mais nous avons besoin de plus. Pour chaque erreur, nous souhaitons stocker des informations supplémentaires:
- Le texte du corps JSON de la demande.
- Le texte de toutes les requêtes SQL générées.
Il y a encore une exigence. Ces informations supplémentaires doivent être enregistrées dans le journal uniquement en cas d'erreur. Sinon, nous n'en avons pas besoin dans les journaux.
Faire cela pour le corps de la demande n'est pas difficile:
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; } } }
Mais pour les requêtes SQL, tout n'est pas si simple. Le fait est que ces requêtes ne sont pas générées par la méthode d'action. Ils ne sont même pas générés dans le contrôleur. Entre la méthode d'action et la méthode de génération SQL, il existe de nombreux appels à d'autres méthodes d'autres classes. Comment extraire le texte de ces demandes lorsque nous en avons besoin?
Une option consiste à utiliser une liste de messages (par exemple, List<string> ). Nous le créons dans notre méthode d'action ( ServiceAction ) et le transmettons à la méthode qui génère SQL. Là, nous ajouterons les textes de requête SQL à cette liste. En cas d'erreur, la méthode d'action aura une liste de messages qui doivent être placés dans le journal.
Cette méthode présente à mon avis un inconvénient très important. Nous devrons transmettre notre liste de messages tout au long de la chaîne d'appels de méthodes jusqu'à ce que nous atteignions la méthode qui génère SQL. Cela signifie que dans de nombreux endroits, cette liste de messages ne sera nécessaire que pour la transmettre. Cela complique le code et j'essaierais de l'éviter.
Si vous utilisez un conteneur DI et que vous pouvez créer vos classes à partir de celui-ci, vous pouvez essayer de placer la liste des messages dans le conteneur avec une durée de vie «par demande». La classe de génération SQL acceptera cette liste de messages comme paramètre constructeur. Une instance de cette classe et une instance du contrôleur pourront alors accéder à la même instance de la liste des messages.
Mais il existe un moyen plus pratique de collecter des informations contextuelles même si vous n'utilisez pas de conteneur DI. Ce serait bien si nous pouvions accéder à la liste des messages via une propriété statique:
public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd) { var message = $"SQL Server query is: {cmd.CommandText}"; ErrorContext.Current.AttachMessage(message); ... }
Il y a un sérieux problème ici. Notre service peut servir simultanément plusieurs demandes. Et chaque demande doit avoir sa propre liste de messages. De plus, lors du traitement d'une seule demande, notre code peut générer plusieurs threads (par exemple, en utilisant async / wait ). Et tous ces threads doivent avoir accès à la même liste de messages. Comment cela peut-il être mis en œuvre?
La AsyncLocal<T> vient à notre aide. Il garantit que si vous mettez de la valeur dans une instance de cette classe dans un thread, vous pouvez obtenir cette valeur dans ce thread, ainsi que dans tous les threads lancés à partir de celui-ci à partir de maintenant. Dans le même temps, tous les autres threads n'auront pas accès à cette valeur.
Regardons l'implémentation de la classe 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(); } }
La méthode CreateNewErrorContext crée instantanément une nouvelle liste de messages et l'enregistre dans le champ CurrentErrorContext de type AsyncLocal . Vous pouvez accéder à la liste actuelle n'importe où dans le code à l'aide de la propriété statique Current . La méthode AttachMessage ajoute un nouveau message à la liste. Il enregistre les messages dans l'instance ConcurrentBag , parce que cette méthode peut être appelée simultanément par plusieurs threads. La méthode GetMessages renvoie tous les messages enregistrés, afin qu'ils puissent être écrits dans le journal.
Vous pouvez maintenant facilement initialiser et utiliser ErrorContext dans 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); } } }
N'importe où dans votre code, vous pouvez ajouter votre message au contexte d'erreur actuel comme suit:
ErrorContext.Current.AttachMessage(message);
Journalisation des performances
Parfois, mon service est lent. Pas pour toutes les requêtes, mais pour certaines, cela prend trop de temps. Je souhaite conserver des informations sur ces demandes afin de les analyser ultérieurement. Comment cela peut-il être mis en œuvre et de quelles informations avons-nous besoin?
Tout d'abord, j'ai besoin d'un seuil d'exécution. Si le traitement de la demande prend moins de temps, tout est en ordre. Je n'écrirai rien dans le journal dans ce cas. Mais si cela prend plus de temps, je dois ajouter des informations au journal.
De quelles informations ai-je besoin? Vous devez absolument savoir combien de temps a duré le traitement des demandes. Mais cela ne suffit pas. Mon service fait beaucoup de choses: vérifier les paramètres des requêtes, obtenir des données d'autres services, créer des requêtes SQL et les exécuter ... J'ai besoin de savoir combien de temps chaque partie a pris pour comprendre où le problème est caché.
De plus, j'ai besoin des mêmes informations que pour les erreurs. J'ai besoin d'un corps de requête pour pouvoir reproduire le problème. J'ai besoin des textes des requêtes SQL au cas où cela prendrait le plus de temps.
Comment y parvenir? Encore une fois, en utilisant la classe 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; } } }
Voyons comment cela fonctionne. La méthode SetCurrentTimer crée un nouveau temporisateur. Ici, vous pouvez spécifier sa description et un seuil d'exécution facultatif.
Pourquoi ce seuil est-il facultatif? Parfois, j'ai besoin d'une partie de mon code pour ne pas courir plus d'un certain temps. Je peux donc souhaiter que toute la demande de service soit traitée en 3 secondes. Dans d'autres cas, je ne veux pas imposer de restrictions sur l'exécution. Par exemple, peu m'importe le temps qu'il faut pour exécuter mes requêtes SQL jusqu'à ce que la totalité de la demande de service soit traitée en moins de 3 secondes. Pour cette raison, pour certains temporisateurs, un seuil d'exécution doit être défini, tandis que pour d'autres, ce n'est pas le cas.
Dans la méthode SetCurrentTimer , un nouveau temporisateur est créé et placé dans la variable CurrentTimer de type AsyncLocal . Mais ce n'est pas tout. À ce stade, un autre temporisateur actif peut déjà exister. Dans ce cas, le nouveau temporisateur que vous venez de créer rejoint celui existant. Cela vous permet de créer des minuteries imbriquées pour mesurer le temps d'exécution à la fois du bloc de code entier et de ses parties:
using (Timer.SetCurrentTimer("The whole block")) { ... using (Timer.SetCurrentTimer("Part 1")) { ... } ... using (Timer.SetCurrentTimer("Part 2")) { ... } ... }
La propriété Current donne accès au temporisateur actuel. Ceci est utile si vous souhaitez y ajouter des messages:
var message = $"SQL Server query is: {cmd.CommandText}"; Timer.Current.AttachMessage(message);
Ici, les messages joints et les temporisateurs imbriqués sont stockés dans des instances de ConcurrentQueue , car leur ordre peut être important.
La propriété Message renvoie les messages collectés dans une seule unité à partir du courant et de tous les temporisateurs qui y sont empilés. Ici , je suis en utilisant JSON-classes de la bibliothèque JSON.NET pour structurer tous les messages. Mais en réalité, ce n'est pas si important. Vous pouvez utiliser n'importe quel format.
La méthode Log écrit les informations stockées dans le minuteur dans le journal, que le seuil d'exécution ait été défini ou non. Dans le même temps, la méthode Dispose écrit des informations dans le journal uniquement si le seuil d'exécution défini a été dépassé.
Nous pouvons maintenant créer un autre attribut pour les méthodes de nos contrôleurs:
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(); } }
et l'utiliser sur des méthodes d'action comme celle-ci:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Conclusion
Dans cet article, j'ai décrit à quel point il est simple de collecter des informations à de nombreux endroits dans le code et d'y accéder plus tard. Cette fonctionnalité peut être implémentée à l'aide de propriétés et de méthodes statiques qui manipulent les instances de la classe AsyncLocal .
J'espère que cet article sera utile pour améliorer le système de journalisation dans vos applications.