Aktuell bin ich als Entwicklungsleiter in einem C# Umfeld eingesetzt. Bei einer Client/ServerApplikation galt es, UseCases zu monitoren und die Laufzeit zu messen. Dabei interessiert besonders
- Anzahl und Dauer der Netzwerkrequests vom Client zum Server
- Art, Anzahl und Dauer der abgesetzten SQL-Statements am Server
- Dauer des Netzwerkresponses vom Server zum Client
und natürlich das selektive Einschalten von Logging für zu überwachende Teilbereiche, wie ich es von Java (sprich von log4j [1]) gewohnt bin.
Der Client loggte bereits mittels der Logging-Implementierung von dot.net, nämlich Systems.Diagnostic.TraceSource. Der Server hatte kein explizites Logging, intern wurden jedoch einige Bibliotheken verwendet, die auf unterschiedliche Arten loggen. Verwendet wurden
Die Aufgabenstellung lautet daher:
- Einführen von Logging auf Client und Serverseite
- Harmonisierung der bestehenden Frameworks
- Zusammenfassung der Logs von Client und Server, um die gewünschten Fakten zu ermitteln
Common.Logging ist kein eigenes Logging Framework, sondern eine Abstraktion (eine "Bridge") von unterschiedlichen Frameworks. Common.Logging erlaubt die konfigurierbare Wahl des Logging-Frameworks, welches die Ausgabe schlussendlich wahrnimmt. Geschaffen wurde die Bibliothek nach dem Vorbild von Commons.Logging (man beachte das "s"), welches dieselbe Aufgabe in der Java-Welt wahrnimmt.
Eine Bibliothek sollte mich durch ihre Verwendung nicht nötigen, andere Frameworks einzusetzen, die gänzlich andere Aspekte abdecken, in diesem Falle Logging. Daher sollten Bibliotheken immer Common.Logging benutzen. D.h. an dieser Stelle ist Kritik an NHibernate angebracht, dass log4net verwendet wird. Ein entsprechender Issue, der die Umstellung auf Common.Logging fordert, existiert bereits in Jira, bitte fleissig voten [4].
Im Folgenden schauen wir uns an, wie wir die oben genannten Anforderungen über log4net und TraceSource abwickeln können.
Die beteiligten Komponenten werden wie folgt verdrahtet:
Sowohl Client als auch Server verwenden Common.Logging, damit muss der rote Teil der Grafik konfiguriert werden. An dieser Stelle soll nicht angeführt werden, wie Common.Logging oder Log4Net zu konfigurieren ist. Dazu sei auf die entsprechenden Homepages verwiesen. Anmerken möchte ich jedoch, dass die Konfiguration von Log4Net sowohl in einem eigenen config-File als auch in der app.config passieren kann. Am Server ist auf jeden Fall das eigene config-File anzustreben, da Log4Net dieses überwachen kann, bei einer Änderung die Datei neu einliest und man damit die Konfiguration zur Laufzeit ändern kann. So kann im Bedarfsfall eine Komponente näher untersucht werden, ohne dass der Server restartet werden muss.
Anbei die Teile der app.config, die notwendig sind, um TraceSource nach Common.Logging über zu führen:
Der erste Block definiert einen Listener (=Appender in der Log4x-Sprache), der das Logging von TraceSource entgegen nimmt und nach Common.Logging überführt. Der zweite Block sorgt dafür, dass System.Trace-Aufrufe nach Common.Logging umgeleitet werden. Hier ist zu beachten, dass ein Default-Listener registriert ist (Log-Window in Visual Studio), welcher mit clear entfernt werden kann. Der dritte Block definiert, dass genau eine Source (= Logger in der Log4x-Sprache), nämlich "System.ServiceModel" mit dem oben definierten Listener verdrahtet wird. Diese Source nimmt die Protokollierung der WCF-Kommunikation vor. Alternativ kann Beginn und Ende der Kommunikation über Aspekte geloggt werden, was zu weniger und sinnvolleren Logging-Outputs führt.
Die Harmonisierung der unterschiedlichen Log-Quellen funktionierte auf diese Art und Weise, wie sieht's nun mit dem Zusammenführen der Outputs von Client und Server aus? Dies kann sehr einfach mit einem Tool wie NetLogClient [5] erfolgen, welches sowohl vom Client als auch vom Server den Output von definierten Loggern über UDP entgegen nimmt und diese zeitlich geordnet visualisiert (NetLogClient ist der C#-Counterpart zu chainsaw).
Client als auch Server verwenden System.Diagnostic.TraceSource, der rote Teil der Grafik muss konfiguriert werden. Auch hier schauen wir uns nur die relevanten Teile an.
Zuerst muss Log4Net nach TraceSource übergeführt werden, in der Konfiguration von Log4Net ist folgendes vorzusehen.
Zweitens ist Common.Logging zu konfigurieren:
Diese Lösung hat den Nachteil, dass drei unterschiedliche Layouts vorhanden sind, die an jeweils unterschiedlichen stellen anzupassen sind, um über die gesamte Architektur einheitliche Layouts zu erhalten. Die Harmonisierung ist damit abgehandelt, die Zusammenführung funktioniert über den Microsoft Service Trace Viewer. Für diesen sind sowohl auf der Client- als auch auf der Serverseite XML-Logs zu erstellen, die dann importiert werden müssen. Zusammengehörige Requests werden in beiden Varianten durch dieselbe Activity-ID identifiziert.
Anbei die Teile der app.config, die notwendig sind, um TraceSource nach Common.Logging über zu führen:
<!-- ************ System.Diagnostics Konfiguration ************ -->
<system.diagnostics>
<!-- Listener für Weiterleitung der Ausgaben von Trace und TraceSource nach Common.Logging registrieren -->
<!-- Der Wert für initializeData gibt an, welche Levels von Trace und TraceSource weiter gegeben werden, -->
<!-- siehe System.Diagnostics.TraceEventType -->
<sharedListeners>
<add name="Diagnostics"
type="Common.Logging.Simple.CommonLoggingTraceListener, Common.Logging"
initializeData="DefaultTraceEventType=Information; LoggerNameFormat={listenerName}.{sourceName}">
</add>
</sharedListeners>
<!-- Bestehende Behandlung von Trace (mit clear) deaktivieren und Listener für Weiterleitung der Ausgaben -->
<!-- von Trace in Common.Logging aktivieren. Damit wird Trace ausschließlich in Common.Logging überführt. -->
<trace>
<listeners>
<clear />
<add name="Diagnostics" />
</listeners>
</trace>
<!-- Bestehende Behandlung von TraceSource (mit clear) deaktivieren und Listener für Weiterleitung der Ausgaben -->
<!-- von TraceSource in Common.Logging aktivieren. Damit wird TraceSource ausschließlich in Common.Logging überführt. -->
<!-- Eine Eigenheit von TraceSource ist, dass alle Sources (= Logger in der Log4Net-Sprache) -->
<!-- einzeln zu Listenern (= Appendern in der Log4Net-Sprache) zugewiesen werden müssen.-->
<sources>
<source name="System.ServiceModel" switchValue="All" propagateActivity="true">
<listeners>
<clear />
<add name="Diagnostics" />
</listeners>
</source>
</sources>
</system.diagnostics>Der erste Block definiert einen Listener (=Appender in der Log4x-Sprache), der das Logging von TraceSource entgegen nimmt und nach Common.Logging überführt. Der zweite Block sorgt dafür, dass System.Trace-Aufrufe nach Common.Logging umgeleitet werden. Hier ist zu beachten, dass ein Default-Listener registriert ist (Log-Window in Visual Studio), welcher mit clear entfernt werden kann. Der dritte Block definiert, dass genau eine Source (= Logger in der Log4x-Sprache), nämlich "System.ServiceModel" mit dem oben definierten Listener verdrahtet wird. Diese Source nimmt die Protokollierung der WCF-Kommunikation vor. Alternativ kann Beginn und Ende der Kommunikation über Aspekte geloggt werden, was zu weniger und sinnvolleren Logging-Outputs führt.
Die Harmonisierung der unterschiedlichen Log-Quellen funktionierte auf diese Art und Weise, wie sieht's nun mit dem Zusammenführen der Outputs von Client und Server aus? Dies kann sehr einfach mit einem Tool wie NetLogClient [5] erfolgen, welches sowohl vom Client als auch vom Server den Output von definierten Loggern über UDP entgegen nimmt und diese zeitlich geordnet visualisiert (NetLogClient ist der C#-Counterpart zu chainsaw).
Die beteiligten Komponenten werden wie folgt verdrahtet:
Zuerst muss Log4Net nach TraceSource übergeführt werden, in der Konfiguration von Log4Net ist folgendes vorzusehen.
<!-- A1 is a TraceAppender and uses PatternLayout --> <!-- Siehe http://logging.apache.org/log4net/release/sdk/log4net.Layout.PatternLayout.html --> <!-- # %date Zeitpunkt in ISO8601DateFormat {ISO8601} oder absolut=ohne Date-Info {ABSOLUTE} --> <!-- # %thread Thread name --> <!-- # %level Used to output the level of the logging event. --> <!-- # %logger Used to output the logger of the logging event. --> <!-- # %ndc NDC (nested diagnostic context) associated with the thread that generated the logging event --> <!-- # %message message --> <!-- # %newline platform dependent line separator character or characters --> <appender name="A1" type="log4net.Appender.TraceAppender"> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%date{ABSOLUTE} [%thread] %-5level %logger %ndc - %message%newline"/> </layout> </appender>
Zweitens ist Common.Logging zu konfigurieren:
<!-- ************ Common.Logging Konfiguration ************ -->
<common>
<logging>
<!-- Common.Logging nach Diagnostic.Trace überführen. -->
<factoryAdapter type="Common.Logging.Simple.TraceLoggerFactoryAdapter, Common.Logging">
<arg key="level" value="DEBUG"/>
<arg key="showLogName" value="true"/>
<arg key="showDataTime" value="true"/>
<arg key="dateTimeFormat" value="yyyy/MM/dd HH:mm:ss:fff"/>
</factoryAdapter>
</logging>
</common>
Diese Lösung hat den Nachteil, dass drei unterschiedliche Layouts vorhanden sind, die an jeweils unterschiedlichen stellen anzupassen sind, um über die gesamte Architektur einheitliche Layouts zu erhalten. Die Harmonisierung ist damit abgehandelt, die Zusammenführung funktioniert über den Microsoft Service Trace Viewer. Für diesen sind sowohl auf der Client- als auch auf der Serverseite XML-Logs zu erstellen, die dann importiert werden müssen. Zusammengehörige Requests werden in beiden Varianten durch dieselbe Activity-ID identifiziert.
Wenn man sich die Konfiguration der beiden Varianten ansieht (und mit Reflector ein bisschen in TraceSource rumschnüffelt), dann merkt man, dass Log4Net und TraceSource unterschiedliche Konzepte verfolgen.
Bei der Implementierung von Log4Net wurde das Observer- und das Mediator-Pattern verwendet. Jeder Logger kennt nur seinen Mediator, was zu leichtgewichtigen Logger-Objekten führt. Deshalb wird beim Einsatz von Log4Net auch fast immer das logger-per-class pattern [6] angewandt.
TraceSource verwendet zwar auch das Observer-, nicht aber das Mediator-Pattern. Deshalb muss für jede Source angegeben werden, welcher Listener den Output erhält. Auch werden Log-Levels nicht vererbt. Dies ist ein Grund, warum Log4Net-Jünger jammern, wenn sie mit TraceSource in Berührung kommen. Tatsächlich steht dahinter ein ganz anderes Konzept: die Logger - Entschuldigung, die Sources sind schwergewichtig, daher wird ein source-per-componente pattern angewandt (Sorry, dazu kenne ich keinen externen Link). Dies erklärt auch, warum die Source nicht über ihren Klassennamen inkl. Namespace von einem zentralen Buffer (Factory) geholt wird, sondern einfach mit new() erzeugt wird. Innerhalb der Komponente müssen die entsprechenden Klassen sehen wie die Source geteilt wird.
Die korrelierende Auswertung mit Microsoft Service Trace Viewer gefällt, schnell war der Wunsch da, auch SQL-Statements in diesem vorzufinden. Gewählt und umgesetzt wurde daher eine Mischvariante aus den obigen zwei Varianten:
Das Thema Logging ist damit aber noch nicht erschöpft, diesen Beitrag möchte ich aber an dieser Stelle beenden. Bitten möchte ich um Voting/Comments von drei Fehlern, die wir im Rahmen der Einführung gefunden haben, nämlich den obig erwähnten Punkt [4], dann noch unnötige Referenzen bei Log4Net [7] und einen Fehler bei der Codeausgabe von Common.Logging [8].
Euer
CL@coopXarch
