Bislang hatte ich dem Thema Ablaufprotokollierung eher wenig Aufmerksamkeit geschenkt. Meldungen im Ausgabefenster mit Debug.WriteLine, selbst gestrickte Protokolldateien – ja, natürlich. Aber das war es dann auch schon. Für meine Arbeit musste ich mich jetzt näher mit dem beschäftigen was das .NET Framework rund um dieses Thema so zu bieten hat. Und ich musste feststellen, dass ich mir wohl nie wieder Gedanken über selbst gestrickte Protokolldateien machen muss. So kam mir die Idee, dieses Thema in einer kleinen Blog-Reihe zu behandeln.
Überblick
Das Problem kennt jeder: die mit Mühen erstellte Anwendung (Klasse, Routine, …) macht irgendwie nicht (immer) das was sie sollte. Aber wo liegt der Fehler? Also Breakpoints setzen und dann Zeile für Zeile den Code debuggen, ab und an mal schauen, was so in den Variablen steht. Komisch, scheint doch alles richtig zu sein?! Also mal ein paar Nachrichtenfenster
MessageBox.Show("Hurz!");an wichtigen Ablaufpunkten eingesetzt und das Ganze noch mal laufen lassen. Zügig ist nun der Fehler eingegrenzt, gefunden und behoben. Wieder laufen lassen, alles O.K.! Prima, dann noch die Nachrichtenfenster entfernen und fertig.
Mal abgesehen davon, dass diese Methode die Gefahr birgt, dass man beim Entfernen der kleinen hilfreichen Nachrichtenfenster mal eines vergisst, welches dann irgendwann den Kunden fröhlich begrüßt (und sicherlich ganz schnell nervt). Wie ermittelt man die Ursache, wenn Probleme erst beim Endanwender auftreten? Oder was tun, wenn die zu prüfende Datenmenge einfach viel zu komplex/umfangreich ist, als dass man sie einfach mal auf dem Bildschirm ausgeben könnte? Man wird wohl einfach aktuelle Werte oder sonstige Informationen in Textdateien schreiben (oder auf die Konsole, oder in das Windows Eventlog, oder, oder, oder) und somit den Ablauf des Programms protokollieren…
Wozu aber das Rad neu erfinden, wenn uns das .NET Framework genau dafür bereits vorgefertigte Lösungen in Form der Klassen Trace und Debug liefert?
Trace und Debug
Die beiden Klassen findet man im Namespace System.Diagnostics. Die Funktionalität der Klassen ist nahezu identisch, der wesentliche Unterschied ist, dass Debug nur dann Ausgaben erzeugt wenn die #DEBUG Konstante definiert ist und Trace nur dann wenn die #TRACE Konstante definiert ist. Im Standard sind für die Build Konfiguration Debug beide Konstanten definiert, für Release aber nur #TRACE. Sie können dies in den Projekteigenschaften auf dem Reiter Erstellen einstellen. Im Folgenden gehen wir von der Standardeinstellung aus.
Ein einfaches Beispiel
Um einen ersten Eindruck zu bekommen, erstellen wir eine einfache Konsolenanwendung. Dabei sieht unsere program.cs wie folgt aus:
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
Console.WriteLine("Beispiel 1");
Trace.WriteLine("Logging: Eintrag mit Trace");
Debug.WriteLine("Logging: Eintrag mit Debug");
Console.ReadLine();
}
}
}Wenn wir die Anwendung nun in der Entwicklungsumgebung starten, erhalten wir je nach Build Konfiguration im Ausgabefenster die folgende Ausgabe
bzw.
Innerhalb der Entwicklungsumgebung können wir nun unsere Informationen verfolgen. Um außerhalb der Entwicklungsumgebung mit Trace und Debug zu arbeiten, müssen wir aber einen Mechanismus einrichten, der die gesendeten Meldungen an das gewünschte Ausgabemedium leitet.
Der Einfachheit halber werde ich in den nachfolgenden Beispielen nur noch die Ausgabe über Trace verwenden. Somit ist die Ausgabe unabhängig von der eingestellten Build Konfiguration.
TraceListener
Ablaufverfolgungsmeldungen werden von sogenannten TraceListenern empfangen. Dieser sogt dann dafür, dass die empfangenen Meldungen an ein entsprechendes Ausgabeziel weitergeleitet werden. Dies können Dateien, das Konsolenfenster oder auch Datenbanken sein. Wenn nötig formatiert der TraceListener auch die Ausgabe.
Obwohl nicht direkt ersichtlich benutzt auch unser erstes Beispiel einen TraceListener, nämlich einen vom Typ DefaultTraceListener. Dieser gibt die mit Write oder WriteLine gesendeten Meldungen über die Windows-API-Funktion OutputDebugString über den angeschlossenen Debugger aus – in unserem Fall das Ausgabefenster des Entwicklungsumgebung. Der DefaultTraceListener wird als einziger Listener automatisch in alle Listener-Ausflistungen eingetragen.
Wichtig: Debug und Trace nutzen eine gemeinsame Listeners-Auflistung, d. h. ein in eine Debug.Listeners-Auflistung eingefügter Listener wird auch zur Trace.Listeners-Auflistung hinzugefügt und umgekehrt.
Ausgabe im Konsolenfenster
Bei unserer kleinen Konsolenanwendung bietet es sich an, die Trace/Debug-Meldungen auch auf der Konsole auszugeben. Dazu verwenden wir einen ConsoleTraceListener. Das Programm ändert sich wie folgt:
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
ConsoleTraceListener listener = new ConsoleTraceListener();
Trace.Listeners.Add(listener);
Console.WriteLine("Beispiel 2.1");
for (int i = 1; i < 10; i++)
{
Console.WriteLine(i);
Trace.WriteLine(string.Format("Logging: Eintrag {0} mit Trace", i));
}
Console.ReadLine();
}
}
}Wird das Programm gestartet erhalten wir folgende Ausgabe:
Zudem finden wir die Meldungen auch im Ausgabefenster.
Dadurch, dass Konsolenausgabe und Trace-Meldungen bunt gemischt auf der Konsole ausgegeben werden, ist diese Form nicht gerade übersichtlich. Zudem ist nicht zwingend zu erkennen, welche Ausgaben denn gewünschte Programmausgaben und welche Trace-Meldungen sind. Daher kann der ConsoleTraceListener seine Ausgabe auch auf dem Fehlerkanal der Konsole ausgeben. Dazu muss nur beim Erstellen des Listeners der optionale Parameter useErrorStrem angegeben und auf True gesetzt werden.
ConsoleTraceListener listener = new ConsoleTraceListener(true);
Jetzt kann die Trace-Ausgabe z. B. in eine Datei umgeleitet werden. Der nachfolgende Konsolenaufruf blendet z. B. die Standardausgabe aus und zeigt nur die Trace-Meldungen.
Direkte Ausgabe in eine Datei
Die Ausgabe auf die Konsole mag für Konsolenanwendungen ja noch sinnvoll sein, aber spätestens wenn das Programm nicht in einem Konsolenfenster läuft, müssen die Ausgaben irgendwie gesammelt werden. Die nächstliegende (und wahrscheinlich auch am weitesten verbreitete) Form ist sicherlich die Ausgabe in eine Datei.
Auch dafür gibt es einen vorgefertigten TraceListener, den TextWriterTraceListener.
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
TextWriterTraceListener listener = new TextWriterTraceListener("trace.log");
Trace.Listeners.Add(listener);
Trace.Listeners.Remove("Default");
Console.WriteLine("Beispiel 3.1");
Trace.WriteLine("Beispiel 3.1 gestartet: " + DateTime.Now.ToString());
for (int i = 1; i < 10; i++)
{
Console.WriteLine(i);
Trace.WriteLine(string.Format("Logging: Eintrag {0} mit Trace", i));
}
Console.ReadLine();
Trace.Flush();
}
}
}In diesem Beispiel werden die Meldungen nur in die Datei geschrieben und nicht wie bisher auch in das Ausgabefenster, da der Standard-Listener aus der Liste entfernt wurde.
Wichtig ist, dass nach der zuletzt abgesetzten Meldung ein Trace.Flush erfolgt, da sonst nicht alle Daten in die Datei geschrieben werden. Wenn Sie möchten, dass die Trace-Meldungen sofort in die Datei geschrieben werden und nicht nach jedem Trace-Aufruf ein Trace.Flush() platzieren möchten (kann man ja mal vergessen), können Sie mit
Trace.AutoFlush = true;
auch dafür sorgen, dass nach jedem Trace Schreibzugriff automatisch ein Trace.Flush erfolgt.
Nach dem ersten Ausführen des Programms finden Sie je nach Build Kofuguration im Ordner bin/Debug oder bin/Release die Datei trace.log. Diese sieht wie folgt aus
Beispiel 3.1 gestartet: 22.05.2013 18:34:17 Logging: Eintrag 1 mit Trace Logging: Eintrag 2 mit Trace Logging: Eintrag 3 mit Trace Logging: Eintrag 4 mit Trace Logging: Eintrag 5 mit Trace Logging: Eintrag 6 mit Trace Logging: Eintrag 7 mit Trace Logging: Eintrag 8 mit Trace Logging: Eintrag 9 mit Trace
Führen Sie das Programm erneut aus, werden die Einträge am Ende der vorhandenen Datei angefügt.
Beispiel 3.1 gestartet: 22.05.2013 19:34:17 Logging: Eintrag 1 mit Trace Logging: Eintrag 2 mit Trace Logging: Eintrag 3 mit Trace Logging: Eintrag 4 mit Trace Logging: Eintrag 5 mit Trace Logging: Eintrag 6 mit Trace Logging: Eintrag 7 mit Trace Logging: Eintrag 8 mit Trace Logging: Eintrag 9 mit Trace Beispiel 3.1 gestartet: 22.05.2013 19:37:39 Logging: Eintrag 1 mit Trace Logging: Eintrag 2 mit Trace Logging: Eintrag 3 mit Trace Logging: Eintrag 4 mit Trace Logging: Eintrag 5 mit Trace Logging: Eintrag 6 mit Trace Logging: Eintrag 7 mit Trace Logging: Eintrag 8 mit Trace Logging: Eintrag 9 mit Trace
Schalter für die Ablaufprotokollierung
Eine weitere Möglichkeit die Ablaufprotokollierung zu beeinflussen sind Schalter, die durch die beiden Schalterklassen BooleanSwitch und TraceSwitch zur Verfügung gestellt werden.
Die Schalterklasse BooleanSwitch kann dabei am ehesten mit einem An-/Ausschalter verglichen werden, die Ausgaben sind also entweder aktiviert oder deaktiviert.
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
TextWriterTraceListener listener = new TextWriterTraceListener("trace.log");
Trace.Listeners.Add(listener);
Trace.Listeners.Remove("Default");
Trace.AutoFlush = true;
Console.WriteLine("Beispiel 4");
BooleanSwitch traceSwitch = new BooleanSwitch("MeinSchalter", "Ablaufprotokollierung mit Schalter");
traceSwitch.Enabled = true;
Trace.WriteLineIf(traceSwitch.Enabled, "Beispiel 4 gestartet: " + DateTime.Now.ToString());
for (int i = 1; i < 10; i++)
{
Console.WriteLine(i);
traceSwitch.Enabled = (i % 2 == 1);
Trace.WriteLineIf(traceSwitch.Enabled, string.Format("Logging: Eintrag {0} mit Trace", i), "Kageorie");
}
Console.ReadLine();
}
}
}Der Konstruktor der Schalterklasse erwartet lediglich eine Bezeichnung, sowie eine Beschreibung. Optional kann der Initialwert angegeben werden. Um die Ausgabe nun Abhängig vom Schalterwert zu beeinflussen bieten sich die Methoden Trace.WriteIf bzw. Trace.WriteIf an, aber natürlich kann auch ein Trace.WriteLine in einen if-Block verschachtelt werden.
Die Protokolldatei sieht dann wie folgt aus:
Beispiel 4 gestartet: 22.05.2013 19:47:30 Kageorie: Logging: Eintrag 1 mit Trace Kageorie: Logging: Eintrag 3 mit Trace Kageorie: Logging: Eintrag 5 mit Trace Kageorie: Logging: Eintrag 7 mit Trace Kageorie: Logging: Eintrag 9 mit Trace
Will man die Trace-Ausgabe hingegen nach Informationsebenen steuern, verwendet man ein TraceSwitch-Objekt. Die Eigenschaft Level, die vom Enumerationstyp TraceLevel ist, bestimmt dabei welche Informationen zur Ausgabe gelangen. Dabei gilt, dass eine höhere Ebene immer auch die Informationen aller niedrigeren Ebenen anzeigt. Die nachfolgende Tabelle zeigt die möglichen Werte.
| Konstante | Wert | Art der ausgegebenen Meldungen |
| Off | 0 | Keine |
| Error | 1 | Fehlermeldungen |
| Warning | 2 | Fehler- und Warnmeldungen |
| Info | 3 | Fehler-, Warn- und Informationsmeldungen |
| Verbose | 4 | Alle Meldungen |
Der Konstruktor des TraceSwitch-Objekts ist identisch zum BooleanSwitch, auch hier werden nur Name, Beschreibung und optional der Startwert des TraceLevels benötigt.
Die TraceSwitch-Klasse besitzt mit den Methoden
- TraceError
- TraceWarning
- TraceInfo
- TraceVerbose
vier Eigenschaften die je nach Schalterstellung True oder False zurückgeben und an WriteIf bzw. WriteLineIf übergeben werden können. Auch hier wird berücksichtigt, dass höhere Trace-Level niedrigere Level enthalten. Hat z. B. Level den Wert TraceLevel.Info, so haben TraceError, TraceWarning und TraceInfo den Wert True und TraceVerbose den Wert False. Beim Wert TraceLevel.Off liefern alle vier Eigenschaften den Wert False.
Das nachfolgende Beispiel zeigt alle Ausgaben bis einschließlich Trace-Level Info.
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
TextWriterTraceListener listener = new TextWriterTraceListener("trace.log");
Trace.Listeners.Add(listener);
Trace.Listeners.Remove("Default");
Trace.AutoFlush = true;
Console.WriteLine("Beispiel 5");
TraceSwitch traceSwitch = new TraceSwitch("MeinSchalter", "Ablaufprotokollierung mit Schalter");
traceSwitch.Level = TraceLevel.Info;
Trace.WriteLine("Beispiel 5 gestartet: " + DateTime.Now.ToString());
Trace.WriteLineIf(traceSwitch.TraceError, "Logging: Eintrag mit TraceLevel Error");
Trace.WriteLineIf(traceSwitch.TraceWarning, "Logging: Eintrag mit TraceLevel Warning");
Trace.WriteLineIf(traceSwitch.TraceInfo, "Logging: Eintrag mit TraceLevel Info");
Trace.WriteLineIf(traceSwitch.TraceVerbose, "Logging: Eintrag mit TraceLevel Verbose");
Console.ReadLine();
}
}
}Hier die Protokolldatei:
Beispiel 5 gestartet: 22.05.2013 19:48:28 Logging: Eintrag mit TraceLevel Error Logging: Eintrag mit TraceLevel Warning Logging: Eintrag mit TraceLevel Info
Steuerung über Konfigurationsdateien
Wozu aber braucht man nun die Schalter, wenn die Ausgaben doch durch fest codierte Bedingungen gesteuert werden, was man dann ja auch mit selbst definierten Konstanten erledigen könnte? Bislang haben wir Schalter und Listener immer programmgesteuert erstellt und deren Werte gesetzt. Dies kann jedoch auch in der Anwendungskonfigurationsdatei geschehen.
Wir fügen unserem Programm eine Anwendungskonfigurationsdatei hinzu und diese sieht dann wie folgt aus:
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<switches>
<add name="MeinSchalter" value="INFO" />
</switches>
<trace autoflush="true">
<listeners>
<add name="FileTraceListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="trace.log" />
<remove name="Default" />
</listeners>
</trace>
</system.diagnostics>
</configuration>Da wir ja nun die Einstellungen über unsere Konfigurationsdatei holen, ändert sich auch unser Programm
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
Console.WriteLine("Beispiel 6");
TraceSwitch traceSwitch = new TraceSwitch("MeinSchalter", "Ablaufprotokollierung mit Schalter");
Trace.WriteLine("Beispiel 6 gestartet: " + DateTime.Now.ToString());
Trace.WriteLineIf(traceSwitch.TraceError, "Logging: Eintrag mit TraceLevel Error");
Trace.WriteLineIf(traceSwitch.TraceWarning, "Logging: Eintrag mit TraceLevel Warning");
Trace.WriteLineIf(traceSwitch.TraceInfo, "Logging: Eintrag mit TraceLevel Info");
Trace.WriteLineIf(traceSwitch.TraceVerbose, "Logging: Eintrag mit TraceLevel Verbose");
Console.ReadLine();
}
}
}Die Ausgabe in der Protokolldatei ist identisch zur vorhergehenden Version ohne Konfigurationsdatei.
Beispiel 6 gestartet: 22.05.2013 19:52:19 Logging: Eintrag mit TraceLevel Error Logging: Eintrag mit TraceLevel Warning Logging: Eintrag mit TraceLevel Info
Ändern wir nun z. B. den Wert des Trace-Levels in “ERROR” und lassen das Programm erneut laufen, sieht die Protokolldatei wie folgt aus:
Beispiel 6 gestartet: 22.05.2013 19:52:19 Logging: Eintrag mit TraceLevel Error Logging: Eintrag mit TraceLevel Warning Logging: Eintrag mit TraceLevel Info Beispiel 6 gestartet: 22.05.2013 19:53:12 Logging: Eintrag mit TraceLevel Error
Welchen Vorteil bietet aber die Vorgehensweise, Einstellungen über die Konfigurationsdatei vorzunehmen? Ganz einfach, man kann die Trace-Ausgabe verändern ohne das Programm verändern zu müssen!
In der Einrichtungsphase werden alle Nachrichten angezeigt.
Weitere Möglichkeiten
Mit dem bisher gezeigten sind die Möglichkeiten der Ablaufprotokollierung natürlich noch nicht ausgeschöpft.
Um die Lesbarkeit der Trace-Ausgabe zu erhöhen können diese eingerückt werden. Wie einfach das geht zeigt das folgende Beispiel:
using System;
using System.Diagnostics;
namespace Logging
{
class Program
{
static void Main(string[] args)
{
Console.WriteLine("Beispiel 7");
Trace.WriteLine("Beispiel 7 gestartet: " + DateTime.Now.ToString());
Trace.IndentLevel = 0;
Trace.IndentSize = 4;
traceIndentTest(0);
Trace.WriteLine("Beispiel 7 beendet.");
Console.ReadLine();
}
private static void traceIndentTest(int level)
{
if (level < 10)
{
Trace.WriteLine("Trace mit IndentLevel: " + Trace.IndentLevel.ToString());
Trace.Indent();
traceIndentTest(level + 1);
}
Trace.Unindent();
}
}
}Die Ausgabe in der Log-Datei sieht dann so aus:
Beispiel 7 gestartet: 22.05.2013 19:54:05
Trace mit IndentLevel: 0
Trace mit IndentLevel: 1
Trace mit IndentLevel: 2
Trace mit IndentLevel: 3
Trace mit IndentLevel: 4
Trace mit IndentLevel: 5
Trace mit IndentLevel: 6
Trace mit IndentLevel: 7
Trace mit IndentLevel: 8
Trace mit IndentLevel: 9
Beispiel 7 beendet.Zudem gibt es auch noch weitere TraceListener, von denen ich auf drei noch ganz kurz eingehen möchte.
EventLogTraceListener
Mit diesem Listener können die Trace-Meldungen an die Windows Ereignisanzeige gesendet werden. Dabei sollte man aber mit den Meldungen etwas sparsam umgehen, damit das Ereignisprotokoll nicht zu schnell voll läuft (z. B. Warnungen, Fehlermeldungen, und Start- und Stopp-Meldungen). Besonders geeignet ist diese Variante z. B. für Windows- oder Web-Dienste.
XmlWriterTraceListener
Ein weiterer Dateibasierter TraceListener, der die Ausgabe in einer XML-Struktur einträgt.
DelimitedListTraceListener
Dieser TraceListener würde mit dem .NET Framework 2.0 eingeführt und schreibt seine Informationen – wie der Name schon vermuten lässt – mit Trennzeichen (Delimiter) in eine Datei. Damit eignet sich dieser Listener sehr gut dafür CSV-Dateien zur weiteren Verarbeitung/Auswertung zu erzeugen. Auch wenn mit den Methoden Trace.TraceInformation, Trace.TraceWarning und Trace.TraceError und den Eigenschaften Trace.TraceOutputOptions und Trace.Delimiter die Ausgabe über diesen TraceListener möglich ist, ist dieser doch eher für die Trace-Ausgabe mit der Klasse TraceSource ausgelegt. Auf diese Klasse und auch den DelimitedListTraceListener wird im nächsten Teil dieser Blog-Serie näher eingegangen.
Ausblick
Dies war der erste Teil der Artikelreihe über Ablaufprotokollierung. Im zweiten Teil dieser Reihe werden wir uns der Klasse TraceSource widmen, die mit dem .Net Framework 2.0 eingeführt wurde und sich flexibler als die Trace-Klasse erweist.
Dateien:
Sourcecode der Beispiele (C#)
Sourcecode der Beispiele (VB.NET)
Ablaufprotokollierung Teil 1 im PDF-Format