HowTo: Logging mit Log4Net

Sobald die Anwendung läuft und die ersten Bugs vom Kunden werden ist es enorm wichtig zu wissen, was eigentlich vorgegangen ist und wie es zu dem Fehler gekommen ist. An wichtigen Punkten ein Logging einzubauen ist deshalb sehr hilfreich beim Debuggen. Log4Net ist eine sehr schicke Logging Bibliothek, die fast jeden Wunsch erfüllt und das ganze in nur wenigen Minuten aufgesetzt.

Log4Net
Log4Net ist eine sehr praktische .NET Bibliothek, welche das Logging vereinfach. Dabei gibt es verschiedene "Log Stufen" (Debug, Error, Info…) und verschiedene Arten des Loggings ("Appender"), so kann man beispielsweise ins Visual Studio Debug Fenster "loggen" oder in eine Datei, DB etc.
Das ganze kann über XML zur Laufzeit auch konfiguriert werden, sodass man auch auf dem Produktivsystem die entsprechenden Log Stufen setzen kann.

Eine gute Einführung findet sich auf den Log4Net Seiten.

Praktischer Einstieg
Um das ganze mal sehr einfach zu Demonstrieren, lege ich ein Consolen Program an und binde die Log4Net DLL ein. Die "log4net.dll" bekommt man von hier.

Konfiguration von Log4Net
Log4Net kann man sehr simpel über die App/Web.Config konfigurieren. Dafür legen wir in unserem Beispiel die "App.config" an:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>
  <log4net>
    <appender name="DebugAppender" type="log4net.Appender.DebugAppender" >
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>
    <root>
      <level value="All" />
      <appender-ref ref="DebugAppender" />
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Erklärung:

Oben definieren wir uns eine eigene ConfigSections, sodass alles zentral geregelt werden kann.

In dieser log4net-Section kommen die verschiedenen "Appender" zum Einsatz. Je nach Appender wird anders geloggt, der "ConsoleAppender" loggt beispielsweise auf die Kommandozeile und der "DebugAppender" in das Visual Studio Output Fenster. Weitere Appender finden sich hier: Config Examples. In einem Appender kann jeweils noch Layout vorgegeben werden, sodass man die Log Message entsprechend anpassen kann.

Im letzten Abschnitt legen wir das Level fest, welches geloggt werden soll – bei uns erstmal alles und wir nutzen die beiden definierten Appender.

"Logging Code"

    class Program
    {
        static void Main(string[] args)
        {
            log4net.Config.XmlConfigurator.Configure();
            ILog logger = LogManager.GetLogger(typeof (Program));

            logger.Debug("Hello World!");
            logger.Error("D´oh!");

            Console.ReadLine();
        }
    }

In der Zeile 5 veranlassen wir Log4Net in der XML Config nachzusehen und dann holen wir uns unseren Logger. Der Logger hat dabei für jedes "Log Level" eine Methode:

Ergebnis:

Wenn ich nun die Anwendung starte, habe ich folgende Ausgabe in der Konsole:

… und dies im Output Fenster im Visual Studio:

Wo genau soll man loggen?

Eine Grundregel habe ich nicht gefunden, allerdings ist der Sinn des Loggens ja, nachzuverfolgen wie ein Fehler zustande kam. Daher könnte man z.B. bei einer Methode die Parameter rausloggen, wichtige "Aufrufe von anderen Services" sowie die Ausgabe loggen. So bekommt man ein Gefühl dafür wie der Code intern tickt.

Insbesondere mit dem "DebugAppender" ist es ganz witzig wenn man einen Button auf der Webseite drückt und man sieht wie der Request durch die Schichten geht und die Werte rausloggt – ein nerdiges Vergnügen

[ Download Democode ]

About the author

Written by Robert Mühsig

Robert Mühsig (@robert0muehsig) ist Webentwickler und beschäftigt sich mit Web-Frameworks (vor allem dem ASP.NET MVC Framework) und scheut sich auch nicht vor Javascript. Ansonsten bloggt er über all jene Probleme, die ihm über den Weg laufen. Seit 2008 ist er Microsoft MVP für ASP.NET und er arbeitet bei der T-Systems Multimedia Solutions GmbH in Dresden. Treffen kann man ihn online via Twitter (@robert0muehsig) oder dieser Seite oder bei der .NET User Group Dresden.

3 Responses

1. 

   Andre Loker

   9. May 2009

   Volle Zustimmung, log4net ist überaus nützlich und extrem flexibel. Ich leite z.B. gern mal alle SQL queries von NHibernate in ein eigenes Logfile um, eta so:

    <appender name="LogFileSql" type="log4net.Appender.RollingFileAppender">
   … log file konfigurieren
     </appender>
   …
     <logger name="NHibernate.SQL" additivity="false">
       <level value="DEBUG" />  �
       <appender-ref ref="LogFileSql" />
     </logger>

   Alle Logger, die mit NHibernate.SQL starten werden hier an den LogFileSql appender geschickt, aber nicht mehr an den root appender (additivity="false"). Das Hauplog bleibt lesbarer und zur Not kann man sehen, was genau NH gemacht hat.

   Auch witzig: alle Queries per Webrequest zählen, siehe http://blog.andreloker.de/post/2008/05/09/NHibernate-counting-database-queries-per-web-request.aspx

   (Wobei das mit den NH2 Statistics wohl eher obsolet geworden ist).

   Grüße,
   Andre

   Reply