En lisant le
radar de la technologie ThoughtWorks , je suis tombé sur la technique de la «
journalisation séparée par demande ».
Chez Confirmit, nous utilisons largement la journalisation, et je me demandais comment cette fonctionnalité pouvait être implémentée.
Description du problème
Voyons ce qui est en jeu. Supposons que nous ayons un service Web. À un moment donné, il commence à planter sur les serveurs de production, mais uniquement pour certaines demandes. Par exemple, les plantages se produisent uniquement pour un utilisateur spécifique. Ou seulement sur un point d'accès séparé ... Nous devons trouver une raison. Dans ce cas, la journalisation vient à notre aide.
Nous pouvons insérer suffisamment d'instructions de journalisation dans notre code pour comprendre la cause du problème. Ces instructions correspondent généralement à votre message avec un certain niveau de journal (Debug, Info, Warning, ...). De plus, le journal lui-même a également son propre niveau. Tous les messages avec des niveaux supérieurs au niveau du journal seront enregistrés dans le stockage du journal (fichier, base de données, ...). Si le niveau du message est inférieur au niveau du journal, le message sera simplement rejeté.
Lorsque notre application fonctionne correctement, nous voulons voir le moins d'entrées de journal possible afin que sa taille reste petite. En même temps, si l'application plante, nous voulons que le journal contienne suffisamment d'entrées pour que nous puissions comprendre la cause du problème. La difficulté ici est que nous définissons généralement un niveau d'enregistrement pour tous les enregistreurs dans notre application. Si tout est en ordre, nous maintenons ce niveau élevé (par exemple, Avertissement). Si nous devons rechercher la cause de l'échec, nous l'installons ci-dessous (par exemple, Debug).
Un niveau de journalisation par application
Lorsque nous définissons un niveau de journalisation bas dans l'application, nos magasins de journaux sont remplis d'une masse de messages. Ces messages proviennent de différentes demandes et sont mélangés entre eux, car les demandes peuvent être servies simultanément. Cela entraîne un certain nombre de problèmes potentiels:
- Comment séparer les messages des requêtes problématiques des messages des autres requêtes?
- Les demandes qui n'entraînent pas de plantages passent toujours leur temps à écrire dans le référentiel de journaux, bien que ces messages ne soient jamais utilisés.
- Les messages des demandes réussies prendront de la place dans les référentiels de journaux, bien que ces messages ne soient jamais utilisés.
Honnêtement, ces difficultés ne sont pas insurmontables. Pour séparer les messages des «bonnes» demandes des messages des «mauvaises» demandes, vous pouvez utiliser l'
ID de corrélation . Tous les systèmes modernes de traitement des journaux permettent de filtrer les enregistrements selon divers critères, y compris celui-ci.
La performance n'est généralement pas non plus un problème majeur. Les systèmes de journalisation prennent en charge l'enregistrement asynchrone, donc l'effet d'une journalisation massive n'est généralement pas perturbateur.
Et l'espace disque est maintenant relativement bon marché, donc le stockage de nombreux enregistrements n'est pas un problème. Surtout si nous pouvons supprimer de temps à autre d'anciens enregistrements.
Cependant, pouvons-nous améliorer ce système? Pouvons-nous définir un niveau d'enregistrement distinct pour chaque demande, en fonction de certaines conditions? Je voudrais considérer ce problème ici.
Niveau de journalisation distinct pour chaque demande
Permettez-moi d'indiquer les exigences de la solution que je mettrai en œuvre. Il doit exister un moyen d'établir un niveau d'enregistrement distinct pour chaque demande. Il doit exister un moyen flexible de spécifier les conditions qui déterminent le choix de ce niveau pour une demande spécifique. Et il devrait être possible de modifier ces conditions pendant l'exécution du programme sans avoir à le redémarrer.
Ainsi, la tâche est définie. Commençons.
Je vais créer un service Web simple basé sur .NET Core. Il aura un seul contrôleur:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { ...
Nous discuterons plus tard de l'implémentation de la propriété
Logger . Pour cette application, j'utiliserai la bibliothèque
log4net pour la journalisation. Cette bibliothèque offre une opportunité intéressante. Je parle de l'
héritage de niveau . En bref, si dans la configuration de cette bibliothèque vous dites que le journal avec le nom
X doit avoir le niveau de journalisation
Info , cela signifie que tous les journaux avec des noms commençant par
X. (par exemple,
XY ,
XZ ,
XAB ) hériteront de ce même niveau.
De là vient l'idée originale. Pour chaque demande, je déterminerai en quelque sorte le niveau de journalisation requis. Ensuite, je vais créer un nouveau journal nommé dans la configuration
log4net . Ce journal aura le niveau de journalisation requis. Après cela, tous les objets d'enregistreur créés dans le cadre de la demande en cours doivent avoir des noms commençant par le nom de ce nouveau journal que j'ai créé. Le seul problème ici est que
log4net ne supprime jamais les journaux. Une fois créés, ils existent tout au long de la vie de l'application. Pour cette raison, je crée initialement un journal pour chaque niveau de journalisation possible:
<?xml version="1.0" encoding="utf-8" ?> <log4net> <appender name="Console" type="log4net.Appender.ConsoleAppender"> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%5level [%thread] (%file:%line) - %message%newline" /> </layout> </appender> <appender name="RollingFile" type="log4net.Appender.RollingFileAppender"> <file value="RequestLoggingLog.log" /> <appendToFile value="true" /> <maximumFileSize value="100KB" /> <maxSizeRollBackups value="2" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%level %thread %logger - %message%newline" /> </layout> </appender> <root> <level value="WARN" /> <appender-ref ref="Console" /> <appender-ref ref="RollingFile" /> </root> <logger name="EdlinSoftware.Log.Error"> <level value="ERROR" /> </logger> <logger name="EdlinSoftware.Log.Warning"> <level value="WARN" /> </logger> <logger name="EdlinSoftware.Log.Info"> <level value="INFO" /> </logger> <logger name="EdlinSoftware.Log.Debug"> <level value="DEBUG" /> </logger> </log4net>
Maintenant, j'ai plusieurs journaux avec les noms
EdlinSoftware.Log.XXXX . Ces noms serviront de préfixes des noms de journaux utilisés dans les requêtes. Pour éviter les collisions entre les demandes, je stocke le préfixe calculé pour cette demande dans une instance
AsyncLocal . La valeur de cet objet sera définie dans le nouveau middleware OWIN:
app.Use(async (context, next) => { try { LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context); await next(); } finally { LogSupport.LogNamePrefix.Value = null; } });
Lorsque cette valeur est définie, il est très facile de créer des enregistreurs avec le préfixe de nom souhaité:
public static class LogSupport { public static readonly AsyncLocal<string> LogNamePrefix = new AsyncLocal<string>(); public static ILog GetLogger(string name) { return GetLoggerWithPrefixedName(name); } public static ILog GetLogger(Type type) { return GetLoggerWithPrefixedName(type.FullName); } private static ILog GetLoggerWithPrefixedName(string name) { if (!string.IsNullOrWhiteSpace(LogNamePrefix.Value)) { name = $"{LogNamePrefix.Value}.{name}"; } return LogManager.GetLogger(typeof(LogSupport).Assembly, name); } .... }
Maintenant, il est clair comment obtenir une instance d'enregistreur dans notre contrôleur:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { private ILog _logger; private ILog Logger { get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController))); } .... }
Il ne reste qu'une seule chose: définir en quelque sorte les règles selon lesquelles nous choisissons le niveau de journalisation pour chaque demande. Ce devrait être un mécanisme assez flexible. L'idée de base est d'utiliser des scripts C #. Je vais créer un
fichier LogLevelRules.json , où je définirai un ensemble de paires «règle - niveau de journalisation»:
[ { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/1\"" }, { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/3\"" } ]
Ici
logLevel est le niveau de journalisation souhaité, et
ruleCode est un code C # qui renvoie une valeur booléenne pour la demande donnée. L'application exécutera les codes de règles un par un. La première règle, dont le code retourne vrai, sera utilisée pour définir le niveau de journalisation approprié. Si toutes les règles retournent false, le niveau par défaut sera utilisé.
Pour créer des délégués à partir d'une représentation sous forme de chaîne de règles, la classe
CSharpScript est
utilisée :
public class Globals { public HttpContext context; } internal class LogLevelRulesCompiler { public IReadOnlyList<LogLevelRule> Compile(IReadOnlyList<LogLevelRuleDescription> levelRuleDescriptions) { var result = new List<LogLevelRule>(); foreach (var levelRuleDescription in levelRuleDescriptions ?? new LogLevelRuleDescription[0]) { var script = CSharpScript.Create<bool>(levelRuleDescription.RuleCode, globalsType: typeof(Globals)); ScriptRunner<bool> runner = script.CreateDelegate(); result.Add(new LogLevelRule(levelRuleDescription.LogLevel, runner)); } return result; } } internal sealed class LogLevelRule { public string LogLevel { get; } public ScriptRunner<bool> Rule { get; } public LogLevelRule(string logLevel, ScriptRunner<bool> rule) { LogLevel = logLevel ?? throw new ArgumentNullException(nameof(logLevel)); Rule = rule ?? throw new ArgumentNullException(nameof(rule)); } }
Ici, la méthode
Compile récupère une liste d'objets lus dans le
fichier LogLevelRules.json . Il crée un délégué
coureur pour chaque règle.
Cette liste de délégués peut être enregistrée:
LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile( new LogLevelRulesFileReader().ReadFile("LogLevelRules.json") );
et utilisé à l'avenir:
public static class LogSupport { internal static IReadOnlyList<LogLevelRule> LogLevelSetters = new LogLevelRule[0]; ... public static async Task<string> GetLogNamePrefix(HttpContext context) { var globals = new Globals { context = context }; string result = null; foreach (var logLevelSetter in LogLevelSetters) { if (await logLevelSetter.Rule(globals)) { result = $"EdlinSoftware.Log.{logLevelSetter.LogLevel}"; break; } } return result; } }
Ainsi, lorsque l'application démarre, nous lisons
LogLevelRules.json , convertissons son contenu dans la liste des délégués à l'aide de la classe
CSharpScript et enregistrons cette liste dans le champ
LogSupport.LogLevelSetters . Ensuite, pour chaque demande, nous exécutons des délégués à partir de cette liste pour obtenir le niveau de journalisation.
La seule chose qui reste à faire est de suivre les modifications dans le
fichier LogLevelRules.json . Si nous voulons définir le niveau de journalisation pour certaines requêtes, nous ajoutons une nouvelle règle à ce fichier. Pour forcer notre application à appliquer ces modifications sans redémarrer, il est nécessaire de surveiller le fichier:
var watcher = new FileSystemWatcher { Path = Directory.GetCurrentDirectory(), Filter = "*.json", NotifyFilter = NotifyFilters.LastWrite }; watcher.Changed += (sender, eventArgs) => {
Il convient de noter que, par souci de concision, j'ai omis le code de synchronisation de flux lorsque je travaillais avec le champ
LogSupport.LogLevelSetters . Mais en pratique, une telle synchronisation est nécessaire.
Le code d'application complet peut être trouvé sur
GitHub .
Inconvénients
Le code ci-dessus vous permet de résoudre le problème de la définition d'un niveau de journalisation distinct pour chaque demande. Mais il a un certain nombre de lacunes. Discutons-en.
1. Cette approche modifie les noms des journaux. Ainsi, dans le référentiel de journaux au lieu de "
MyClassLogger ", quelque chose comme "
Edlinsoft.Log.Debug.MyClassLogger " sera stocké. Vous pouvez vivre avec, mais ce n'est pas très pratique. Le problème peut peut-être être résolu en modifiant la disposition du journal (disposition du journal).
2. Il est désormais impossible d'utiliser des instances statiques des classes de consignateurs, car elles doivent être créées séparément pour chaque demande. Le problème le plus grave ici, à mon avis, est que les développeurs doivent toujours garder cela à l'esprit. Quelqu'un pourrait accidentellement créer un champ statique avec un enregistreur et obtenir des résultats étranges. Vous pouvez surmonter cette situation en créant une classe wrapper pour les enregistreurs au lieu d'utiliser directement les classes
log4net . Un tel wrapper peut toujours créer de nouvelles instances d'enregistreurs
log4net pour chaque opération. Dans ce cas, il peut être librement utilisé dans des champs statiques.
3. L'approche décrite crée de nombreuses instances d'enregistreurs. Cela consomme de la mémoire et des cycles de processeur à la fois lors de la création et pendant la récupération de place. Selon votre application, cela peut ou non être un problème important.
4. Lorsque nous modifions le fichier JSON avec les règles, le code de la règle peut contenir des erreurs. Il est très simple d'utiliser des blocs try-catch pour que ces erreurs ne détruisent pas notre application principale. Cependant, nous devons d'une manière ou d'une autre découvrir que quelque chose s'est mal passé. Il existe deux types d'erreurs:
- Erreurs de temps de compilation pour le code de règle dans les délégués.
- Erreurs d'exécution de ces délégués.
D'une manière ou d'une autre, nous devons découvrir ces erreurs, sinon notre enregistrement ne fonctionnera tout simplement pas et nous ne le saurons même pas.
5. Le code de règle dans le fichier JSON peut, en principe, contenir toutes les instructions. Cela pourrait potentiellement entraîner des problèmes de sécurité. Il est nécessaire de limiter en quelque sorte les capacités de ce code. En revanche, si un attaquant est capable d'écrire directement dans les fichiers de votre application, le problème de sécurité est évident.
Conclusion
En général, je n'ai pas eu l'impression qu'une telle solution devrait remplacer l'approche actuelle de la journalisation. Un bon outil avec la possibilité de filtrer les entrées de journal peut aider ici même lorsque vous utilisez un seul niveau de journalisation pour l'application entière. J'espère néanmoins que l'analyse de ce problème vous donnera matière à réflexion.