Best practices in HEC.Logging

Blog – Technik und Methoden
Verfasst von Vladimir Schmidt am 9. Mai 2018

Die Protokollierung gehört zu den nicht-funktionalen Anforderungen. Sie ist eine grundlegende Eigenschaft eines Systems und muss schon im Architekturentwurf berücksichtigt werden. Auf der anderen Seite beeinflusst die Protokollierung kein fachliches Verhalten und wird deswegen oft unterschätzt. Ihre Wichtigkeit wird erst erkannt, wenn die Auswirkungen einer fehlenden Protokollierung sichtbar werden.

Ein Beispiel: Eine Applikation befindet sich längst im Betrieb und hat angeblich ein fehlerhaftes Verhalten gezeigt. Die zu untersuchende Komponente hat keine Protokollierung, und ihre Geschäftslogik ist von Stammdaten abhängig, die in der Zwischenzeit schon geändert wurden. Dann erinnert die Analyse an Detektivarbeit mit zahlreichen Hypothesen und Verdächtigen.

In diesem Blog versuche ich die besten Praktiken in der Protokollierung darzustellen und anhand von Beispielen mit Hilfe des HEC.Logging in Microsoft .NET zu veranschaulichen.

Was ist eigentlich ein Protokoll?

Das Protokoll ist eine zeitliche Reihenfolge von Datensätzen bestimmter Art. Jeder Datensatz beschreibt ein Ereignis, welches innerhalb der Applikation ausgelöst wird. Es wird durch folgende Attribute beschrieben:

  • Auslöser
  • Auslösungszeit
  • Detaillierungsgrad
  • Beschreibung
  • Kontext

Diese Daten ermöglichen es Entwicklern, Kunden, Administratoren und anderen interessierten Personen, die Vorgänge zu interpretieren und die Umstände der Ereignisauslösung zu rekonstruieren.

Dieses Konzept sieht in der Theorie sehr einfach aus, aber es ergeben sich daraus mehrere praktische Fragen: “Wo, wie und was muss man protokollieren?” Oftmals gibt es keine eindeutige Antwort darauf. Im Folgenden formuliere ich die wichtigen Aspekte bei der Protokollierung aus.

Kein Rad neu erfinden

Es gibt mehrere Frameworks für Protokollierung: Log4net, NLog, Serilog, usw. Sie unterscheiden sich oft kaum in der Funktionalität und haben manchmal identische Namen der Methoden. Meine Auswahl ist Log4Net Framework, da dies eine .NET Variante des bekanntesten Frameworks Log4j ist und sich über die Zeit zu einem De-facto-Standard der Protokollierung entwickelte. Es ist zuverlässig und bietet umfangreiche Funktionalität an.

Um die Protokollierung in kleinen und mittleren Projekten zu vereinfachen wurde ein NuGet-Paket HEC.Logging entwickelt. Das Paket ist eine Fassade des Log4Net Framework. Es kann vom internen NuGet-Server der HEC GmbH (Einrichtung des externen Repository in Visual Studio) installiert werden.

Nach der Installation muss man die Komponente wie folgt initialisieren:

  • Einstellungen in Quellcode
    LogManager.Instance.Initialize("log.txt", LogLevel.Debug);
    
  • Einstellungen in der Konfigurationsdatei (app.config, web.config)
    LogManager.Instance.InitializeByXmlConfiguration();
    

Danach kann man in jeder Klasse ein privates statisches Feld mit Logger anlegen und desen Methoden innerhalb einzelner Methoden aufrufen, um den Vorgang zu protokollieren.

using HEC.Logging;

public class SampleService
{
	private static readonly ILogger Log = LogManager.GetLogger(typeof(SampleService));

	public void Process()
	{
		Log.Info("Start");
		// ...
		Log.Info("Stop");
	}
}

Detaillierungsgrad

Nicht jede Information ist für alle gleich wichtig. Der Detaillierungsgrad beschreibt, auf welcher Ebene man den Vorgang betrachtet (von fachlicher bis zu technischer Ebene). Er erleichtert die Zuordnung der Datensätze zu den Interessenten. Für kleine/mittlere Applikationen sind folgende sechs Stufen ausreichend:

Level Art der Information Interessenten
Fatal Komponente kann nicht gestartet werden Administrator
Error Operation kann nicht abgeschlossen werden Kunde
Warn ein Fehler ist aufgetreten, aber die Operation wird weiter ausgeführt Kunde
Info grobe fachliche Schritte (gestartet, beendet) Kunde
Debug einzelne fachliche Schritte Support, Entwickler1), QS1)
Trace einzelne technische Schnitte Support2), Entwickler1), QS1)

1)nur in Testumgebung
2)nur für einzelne Komponente in produktiver Umgebung

Je nach Grad muss die Beschreibung entsprechende Daten enthalten. Zum Beispiel sind ein interner Datenbankschlüssel oder der Fortschritt eines Algorithmus mit Level Trace zu protokollieren. Level Info wäre falsch, da es sich nicht um eine relevante Information für den Kunden handelt.

In der Regel definiert man einen minimalen Detaillierungsgrad für die ganze Applikation. Das sind Trace für eine Testumgebung und Debug für eine produktive Umgebung. Bei der Analyse kann man diesen Wert temporär für die einzelnen Klassen ändern.

public class SampleService
{
	private static readonly ILogger Log = LogManager.GetLogger(typeof(SampleService));
	private readonly IStorage storage;

	public void Process(string filename)
	{
		Log.DebugFormat("Start processing file={0}", filename);

		Log.Trace("Reading data from storage");
		var content = this.storage.GetContent(filename);
		if (content.Length == 0)
		{
			Log.ErrorFormat("Processing file={0} failed because the file content is empty", filename);
			throw new InvalidOperationException("file content is empty");
		}

		Log.Trace("Doing something");
		// ...

		Log.Trace("Doing something else");

		Log.DebugFormat("Stop processing file={0}", filename);
	}
}

Beschreibung

Das Protokoll schreibt man für Entwickler, Support, QS, Anforderungsmanagement, Kunden, also für Menschen. Jeder Interessent muss die gewünschte Information leicht finden. Deswegen sollte man komplexere oder längere Texte, mehrere nacheinander folgende Texte oder binäre Datenformate vermeiden. Die Beschreibung muss kompakt und ohne Zeilenumbrüche sein. Als Speichermedium ist eine lokale Text-Datei oft die beste Auswahl.

// technische Information für Level > Debug
Log.Info("Processing user with FXId < 2 and isResponsible == true");

 // Zeilenumbruch
Log.Error("Error because of the field FXId < 2\nCheck dump");

// nicht informativ
Log.Fatal("Something wrong with file");

// DEBUG anstatt ERROR
Log.DebugFormat("File {0} not found", filename);

// INFO anstatt DEBUG
Log.Info("Fahrzeug nicht gefunden. Erstelle ein neues Fahrzeug.");

Zusätzliche Daten

Die Beschreibung kann mit zusätzlichen Attributen wie Name des Nutzers, Name der Datei, interner Schüssel usw. ergänzt werden. Am besten müssen diese Attribute in ein lesbares Format umgewandelt und in die Beschreibung eingebettet werden. Es gibt zwei passende Darstellungen:

  • JSON
    var model = new { Name = "Peter" };
    Log.TraceFormat("Model: {0}", JsonConvert.SerializeObject(model));
    // Model: { Name: "Peter" }
    
  • Key-Value
    Log.TraceFormat("User with name={0} and surname={1}", "Peter", "Penn");
    // User with name=Peter and surname=Penn
    

Hier werden parametrisierte Varianten der Protokollierungsmethoden benutzt

Log.TraceFormat(string message, params object[] parameters);
// usw.

wobei die Parameter parameters in Text umgewandelt und ins Textmuster message eingebettet werden.

Wenn man ein Objekt als Parameter übergibt, wird dessen ToString-Methode aufgerufen, um das Objekt in den Text umzuwandeln. Dies kann man weiter anpassen. Im folgenden Beispiel wird das Objekt in JSON umgewandelt. Die Umwandlung wird nur dann gestartet, wenn der entsprechende Detaillierungsgrad aktiv ist.

public class SampleParser
{
	private static readonly ILogger Log = LogManager.GetLogger(typeof(SampleParser));

	public Model Parse(string content)
	{
		Log.TraceFormat("Input={0}", content);

		var model = new Model();
		// ....

		Log.TraceFormat("Model={0}", JsonString.From(model));

		return model;
	}
}

public class JsonString
{
	private readonly object model;

	private JsonString(object model)
	{
		this.model = model;
	}

	public override string ToString()
	{
		return JsonConvert.SerializeObject(this.model);
	}

	public static JsonString From(object model)
	{
		return new JsonString(model);
	}
}

Kontext mitprotokollieren

Wenn eine Operation nicht abgeschlossen werden kann und die Schnittstelle eine Ausnahme auslöst, muss die Fehlermeldung ins Protokoll geschrieben werden. Am besten speichert man in der Beschreibung alle benötigte Daten, die für die Interpretation wichtig sind.

Im folgenden Beispiel werden alle Zeilen einer Datei verarbeitet. Wenn eine Zeile eine Ausnahme auslöst, muss man die Fehlermeldung mit der fehlgeschlagenen Zeile ins Log speichern.

public void Process(string filename)
{
	Log.TraceFormat("Start processing file={0}", filename);

	var lines = FileSystem.Current.ReadAllLines(filename, Encoding.UTF8);
	foreach (var line in lines)
	{
		try
		{
			this.SubProcess(line);
		}
		catch (ArgumentException exc)
		{
			Log.WarnFormat("Processing line={0} skipped because of {1}", line, exc);
		}
		catch (Exception exc)
		{
			Log.ErrorFormat("Processing item={0} failed because of {1}", line, exc);
			throw new InvalidOperationException("Processing failed", exc);
		}
	}

	Log.TraceFormat("Processing file={0} finished", filename);
}

Bedingte Protokollierung

Falls ein Vorgang nur unter bestimmten Konditionen protokolliert werden muss, kann man eine bedingte Anweisung schreiben.

if (content.Length > 1024) {
	Log.Warn("The file is too large");
}

Dabei muss man entweder einen Unit-Test für diesen Codeabschnitt schreiben oder die verschlechterte Testabdeckung akzeptieren. Beide Lösungen sind nicht zielführend. Stattdessen muss man die Methoden mit einem booleschen Parameter nutzen, der festlegt, ob die Information ins Protokoll geschrieben wird.

Log.TraceWhen(string message, bool condition);
Log.When(bool option).Trace(string message);
Log.When(bool option).TraceFormat(string message, params object[] parameters);
// usw.

Im folgenden Beispiel wird eine Warnung ins Log geschrieben, sobald die zu verarbeitende Datei größer als 1 KByte ist

public void Process(string filename)
{
	Log.DebugFormat("Start processing file={0}", filename);

	var content = FileSystem.Current.ReadAllText(filename, Encoding.UTF8);
	Log.When(content.Length > 1024)
           .WarnFormat("The file={0} is too large", filename);

	// ...
}

Kommunikation mit externen Systemen

Alle Interaktionen mit externen Systemen müssen protokolliert werden. Unter anderem sind das

  • Datenbankabfragen (SQL-Abfragen)
  • Dateioperationen (Öffnen, Kopieren, Löschen von Dateien)
  • Umwandlung der Eingabedaten (gelesene Modelle)
  • Eingehende und ausgehende Aufrufe von Rest API Schnittstellen

Die Datensätze müssen mit Level Trace protokolliert werden. In Regel ist dieser Detaillierungsgrad in der produktiven Umgebung ausgeschaltet, damit die Anwendung keine Performanz-Probleme hat. Es gibt aber Fälle, in denen sie für einzelne Komponenten temporär oder dauerhaft in der produktiven Umgebung wieder freischaltet werden. Zum Beispiel muss man die Kommunikation mit einem rechtlich fremden System immer protokollieren, um mögliche Missverständnisse mit externen Teams oder Dienstleistern leicht klären zu können.