Beim Lesen von
ThoughtWorks Technology Radar bin ich auf die Technik „
Separate Protokollierung pro Anforderung “ gestoßen. Wir bei
Confirmit nutzen die Protokollierung in großem Umfang, und ich habe mich gefragt, wie diese Funktionalität implementiert werden kann.
Problembeschreibung
Mal sehen, worum es geht. Angenommen, wir haben einen Webdienst. Irgendwann stürzt es auf Produktionsservern ab, jedoch nur bei einigen Anforderungen. Beispielsweise treten Abstürze nur für einen bestimmten Benutzer auf. Oder nur auf einem separaten Zugangspunkt ... Wir müssen einen Grund finden. In diesem Fall hilft uns die Protokollierung.
Wir können genügend Protokollierungsanweisungen in unseren Code einfügen, um die Ursache des Problems zu verstehen. Diese Anweisungen stimmen normalerweise mit einer bestimmten Protokollstufe (Debug, Info, Warnung, ...) Ihrer Nachricht überein. Darüber hinaus hat das Protokoll selbst eine eigene Ebene. Alle Nachrichten mit Ebenen über der Protokollebene werden im Protokollspeicher (Datei, Datenbank, ...) aufgezeichnet. Wenn die Nachrichtenebene niedriger als die Protokollebene ist, wird die Nachricht einfach verworfen.
Wenn unsere Anwendung einwandfrei funktioniert, möchten wir so wenig Protokolleinträge wie möglich sehen, damit ihre Größe klein bleibt. Wenn die Anwendung abstürzt, soll das Protokoll gleichzeitig über genügend Einträge verfügen, damit wir die Ursache des Problems verstehen können. Die Schwierigkeit hierbei ist, dass wir normalerweise eine Protokollierungsstufe für alle Protokollierer in unserer Anwendung festlegen. Wenn alles in Ordnung ist, halten wir dieses Niveau hoch (z. B. Warnung). Wenn wir nach der Fehlerursache suchen müssen, installieren wir sie unten (z. B. Debug).
Eine Protokollierungsstufe pro Anwendung
Wenn wir die Protokollierungsstufe in der Anwendung niedrig einstellen, werden unsere Protokollspeicher mit einer Vielzahl von Nachrichten gefüllt. Diese Nachrichten stammen von verschiedenen Anforderungen und werden untereinander gemischt, da Anforderungen gleichzeitig bearbeitet werden können. Dies führt zu einer Reihe potenzieller Probleme:
- Wie trenne ich Nachrichten problematischer Anfragen von Nachrichten anderer Anfragen?
- Anforderungen, die nicht zu Abstürzen führen, verbringen ihre Zeit damit, in das Protokollrepository zu schreiben, obwohl diese Nachrichten niemals verwendet werden.
- Nachrichten von erfolgreichen Anforderungen belegen Speicherplatz in den Protokollrepositorys, obwohl diese Nachrichten niemals verwendet werden.
Ehrlich gesagt sind diese Schwierigkeiten nicht unüberwindbar. Um die Nachrichten der "guten" Anforderungen von den Nachrichten der "schlechten" Anforderungen zu trennen, können Sie die
Korrelations-ID verwenden . Alle modernen Protokollverarbeitungssysteme ermöglichen das Filtern von Datensätzen nach verschiedenen Kriterien, einschließlich dieser.
Leistung ist normalerweise auch kein großes Problem. Protokollierungssysteme unterstützen die asynchrone Aufzeichnung, sodass der Effekt der massiven Protokollierung im Allgemeinen nicht störend ist.
Und der Speicherplatz ist jetzt relativ billig, sodass das Speichern vieler Datensätze kein Problem darstellt. Vor allem, wenn wir von Zeit zu Zeit alte Datensätze löschen können.
Können wir dieses System jedoch verbessern? Können wir abhängig von bestimmten Bedingungen für jede Anforderung eine separate Protokollierungsstufe festlegen? Ich möchte dieses Problem hier betrachten.
Separate Protokollierungsstufe für jede Anforderung
Lassen Sie mich die Anforderungen für die Lösung angeben, die ich implementieren werde. Es muss eine Möglichkeit geben, für jede Anforderung eine separate Protokollierungsstufe einzurichten. Es muss eine flexible Möglichkeit geben, die Bedingungen anzugeben, die die Auswahl dieser Ebene für eine bestimmte Anforderung bestimmen. Und es sollte möglich sein, diese Bedingungen während der Programmausführung zu ändern, ohne sie neu starten zu müssen.
Die Aufgabe ist also festgelegt. Fangen wir an.
Ich werde einen einfachen Webdienst erstellen, der auf .NET Core basiert. Er wird einen einzigen Controller haben:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { ...
Wir werden die Implementierung der
Logger- Eigenschaft später diskutieren. Für diese Anwendung werde ich die
log4net- Bibliothek zum Protokollieren verwenden. Diese Bibliothek bietet eine interessante Gelegenheit. Ich spreche von
Level-Vererbung . Kurz gesagt, wenn Sie in der Konfiguration dieser Bibliothek angeben, dass das Protokoll mit dem Namen
X die
Info- Protokollierungsstufe haben soll, bedeutet dies, dass alle Protokolle mit Namen, die mit
X beginnen (z. B.
XY ,
XZ ,
XAB ), dieselbe Ebene erben.
Von hier kommt die ursprüngliche Idee. Für jede Anfrage werde ich irgendwie den erforderlichen Protokollierungsgrad bestimmen. Dann werde ich ein neues benanntes Protokoll in der
log4net- Konfiguration
erstellen . Dieses Protokoll hat die erforderliche Protokollierungsstufe. Danach sollten alle im Rahmen der aktuellen Anforderung erstellten Logger-Objekte Namen haben, die mit dem Namen dieses von mir erstellten neuen Protokolls beginnen. Das einzige Problem hierbei ist, dass
log4net die Protokolle niemals entfernt. Einmal erstellt, existieren sie während der gesamten Lebensdauer der Anwendung. Aus diesem Grund erstelle ich zunächst ein Protokoll für jede mögliche Protokollierungsstufe:
<?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>
Jetzt habe ich mehrere Protokolle mit den Namen
EdlinSoftware.Log.XXXX . Diese Namen dienen als Präfixe für Protokollnamen, die in Abfragen verwendet werden. Um Kollisionen zwischen Anforderungen zu vermeiden, speichere ich das berechnete Präfix für diese Anforderung in einer
AsyncLocal- Instanz. Der Wert dieses Objekts wird in der neuen OWIN-Middleware festgelegt:
app.Use(async (context, next) => { try { LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context); await next(); } finally { LogSupport.LogNamePrefix.Value = null; } });
Wenn dieser Wert festgelegt ist, ist es sehr einfach, Logger mit dem gewünschten Namenspräfix zu erstellen:
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); } .... }
Jetzt ist klar, wie Sie eine Logger-Instanz in unserem Controller erhalten:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { private ILog _logger; private ILog Logger { get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController))); } .... }
Es bleibt nur eines zu tun: Legen Sie irgendwie die Regeln fest, nach denen wir die Protokollierungsstufe für jede Anforderung auswählen. Dies sollte ein ziemlich flexibler Mechanismus sein. Die Grundidee ist die Verwendung von C # -Skripten. Ich werde eine
LogLevelRules.json- Datei erstellen, in der ich eine Reihe von Paaren mit „Regel - Protokollierungsstufe“ definieren werde:
[ { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/1\"" }, { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/3\"" } ]
Hier ist
logLevel die gewünschte Protokollierungsstufe, und
ruleCode ist C # -Code, der einen booleschen Wert für die angegebene Anforderung zurückgibt. Die Anwendung führt die Regelcodes nacheinander aus. Die erste Regel, deren Code true zurückgibt, wird verwendet, um die entsprechende Protokollierungsstufe festzulegen. Wenn alle Regeln false zurückgeben, wird die Standardstufe verwendet.
Um Delegaten aus einer Zeichenfolgendarstellung von Regeln zu erstellen, wird die
CSharpScript- Klasse
verwendet :
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)); } }
Hier ruft die
Compile- Methode eine Liste von Objekten ab, die aus der Datei
LogLevelRules.json gelesen wurden. Es wird für jede Regel ein
Runner- Delegat erstellt.
Diese Delegatenliste kann gespeichert werden:
LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile( new LogLevelRulesFileReader().ReadFile("LogLevelRules.json") );
und in der Zukunft verwendet:
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; } }
Wenn die Anwendung
gestartet wird , lesen wir daher
LogLevelRules.json , konvertieren den Inhalt mithilfe der
CSharpScript- Klasse in die
Delegatenliste und speichern diese Liste im Feld
LogSupport.LogLevelSetters . Anschließend führen wir für jede Anforderung Delegaten aus dieser Liste aus, um die Protokollierungsstufe abzurufen.
Sie müssen nur noch Änderungen in der Datei
LogLevelRules.json verfolgen . Wenn wir die Protokollierungsstufe für einige Abfragen festlegen möchten, fügen wir dieser Datei eine neue Regel hinzu. Um unsere Anwendung zu zwingen, diese Änderungen ohne Neustart anzuwenden, muss die Datei überwacht werden:
var watcher = new FileSystemWatcher { Path = Directory.GetCurrentDirectory(), Filter = "*.json", NotifyFilter = NotifyFilters.LastWrite }; watcher.Changed += (sender, eventArgs) => {
Es sollte beachtet werden, dass ich der Kürze halber den Stream-Synchronisationscode weggelassen habe, wenn ich mit dem Feld
LogSupport.LogLevelSetters gearbeitet habe . In der Praxis ist eine solche Synchronisation jedoch erforderlich.
Den vollständigen Anwendungscode finden Sie auf
GitHub .
Nachteile
Mit dem oben gezeigten Code können Sie das Problem lösen, für jede Anforderung eine separate Protokollierungsstufe festzulegen. Aber er hat eine Reihe von Mängeln. Lassen Sie uns sie diskutieren.
1. Dieser Ansatz ändert die Namen der Protokolle. Im Protokoll-Repository wird also anstelle von "
MyClassLogger " etwas wie "
Edlinsoft.Log.Debug.MyClassLogger " gespeichert. Sie können damit leben, aber es ist nicht sehr bequem. Möglicherweise kann das Problem durch Ändern des Layouts des Protokolls (Protokolllayout) behoben werden.
2. Es ist jetzt unmöglich, statische Instanzen der Logger-Klassen zu verwenden, da diese für jede Anforderung separat erstellt werden müssen. Das schwerwiegendste Problem hier ist meiner Meinung nach, dass Entwickler dies immer berücksichtigen sollten. Jemand könnte versehentlich ein statisches Feld mit einem Logger erstellen und seltsame Ergebnisse erzielen. Sie können diese Situation überwinden, indem Sie eine Wrapper-Klasse für Logger
erstellen, anstatt
log4net- Klassen direkt zu verwenden. Ein solcher Wrapper kann immer neue Instanzen von
log4net- Loggern für jede Operation erstellen. In diesem Fall kann es in statischen Feldern frei verwendet werden.
3. Der beschriebene Ansatz erstellt viele Instanzen von Loggern. Dies verbraucht Speicher- und Prozessorzyklen sowohl während der Erstellung als auch während der Speicherbereinigung. Abhängig von Ihrer Anwendung kann dies ein wesentliches Problem sein oder auch nicht.
4. Wenn wir die JSON-Datei mit den Regeln ändern, kann der Regelcode Fehler enthalten. Es ist sehr einfach, Try-Catch-Blöcke zu verwenden, damit diese Fehler unsere Hauptanwendung nicht zerstören. Wir müssen jedoch irgendwie herausfinden, dass etwas schief gelaufen ist. Es gibt zwei Arten von Fehlern:
- Kompilierungszeitfehler für Regelcode in Delegaten.
- Laufzeitfehler dieser Delegierten.
Irgendwie müssen wir uns über diese Fehler informieren, sonst funktioniert unsere Protokollierung einfach nicht und wir wissen nicht einmal davon.
5. Der Regelcode in der JSON-Datei kann grundsätzlich beliebige Anweisungen enthalten. Dies kann möglicherweise zu Sicherheitsproblemen führen. Es ist notwendig, die Fähigkeiten dieses Codes irgendwie einzuschränken. Wenn ein Angreifer hingegen direkt in die Dateien Ihrer Anwendung schreiben kann, liegt das Sicherheitsproblem auf der Hand.
Fazit
Im Allgemeinen hatte ich nicht den Eindruck, dass eine solche Lösung den bestehenden Ansatz für die Protokollierung ersetzen sollte. Ein gutes Tool mit der Fähigkeit, Protokolleinträge zu filtern, kann hier hilfreich sein, selbst wenn eine einzelne Protokollierungsstufe für die gesamte Anwendung verwendet wird. Trotzdem hoffe ich, dass die Analyse dieses Problems Sie zum Nachdenken anregen wird.