(B)loggen met Log4Net

Enige tijd gelezen heb ik een stukje geschreven over het loggen met het standaard logging framework van .Net. Op zich  geeft dat al heel veel flexibiliteit bij het loggen maar het kan natuurlijk  altijd beter…

Sinds kort passen wij Log4Net toe. Log4Net is een opensource project en is te downloaden op http://logging.apache.org/log4net/. Log4Net is afgeleid van het log4j projecten wordt gepubliceerd met de Apache license agreement.

De huidige release is al weer enkele jaren oud (maart 2006) en gebaseerd op
.Net 2.0 en het werkt prima.

Log van origami

De grootste voordelen voor ons ten opzichte van het standaard .Net logging framework zijn nu:

  • Betere granulatie (Nu ook Debug en Warning mogelijkheden) en combinaties van loggers en appenders mogelijk
  • Loggen naar een aparte eventlog ipv. de Application eventlog
  • De rolling file heeft meer opties (per dag, per filegrootte, combinaties)

Er zijn nog meer logging mogelijkheden. De lijst van mogelijkheden is echt
lang:

Type Description
log4net.Appender.AdoNetAppender Writes logging events to a database using either prepared statements or
stored procedures.
log4net.Appender.AnsiColorTerminalAppender Writes color highlighted logging events to a an ANSI terminal
window.
log4net.Appender.AspNetTraceAppender Writes logging events to the ASP trace context. These can then be rendered at
the end of the ASP page or on the ASP trace page.
log4net.Appender.BufferingForwardingAppender Buffers logging events before forwarding them to child
appenders.
log4net.Appender.ColoredConsoleAppender Writes logging events to the application’s Console. The events may go to
either the standard our stream or the standard error stream. The events may have
configurable text and background colors defined for each level.
log4net.Appender.ConsoleAppender Writes logging events to the application’s Console. The events may go to
either the standard our stream or the standard error stream.
log4net.Appender.EventLogAppender Writes logging events to the Windows Event Log.
log4net.Appender.FileAppender Writes logging events to a file in the file system.
log4net.Appender.ForwardingAppender Forwards logging events to child appenders.
log4net.LocalSyslogAppender Writes logging events to the local syslog service (UNIX only).
log4net.Appender.MemoryAppender Stores logging events in an in memory buffer.
log4net.Appender.NetSendAppender Writes logging events to the Windows Messenger service. These messages are
displayed in a dialog on a users terminal.
log4net.Appender.OutputDebugStringAppender Writes logging events to the debugger. If the application has no debugger,
the system debugger displays the string. If the application has no debugger and
the system debugger is not active, the message is ignored.
log4net.Appender.RemoteSyslogAppender Writes logging events to a remote syslog service using UDP
networking.
log4net.Appender.RemotingAppender Writes logging events to a remoting sink using .NET remoting.
log4net.Appender.RollingFileAppender Writes logging events to a file in the file system. The RollingFileAppender
can be configured to log to multiple files based upon date or file size
constraints.
log4net.Appender.SmtpAppender Sends logging events to an email address.
log4net.Appender.SmtpPickupDirAppender Writes SMTP messages as files into a pickup directory. These files can then
be read and sent by an SMTP agent such as the IIS SMTP agent.
log4net.Appender.TelnetAppender Clients connect via Telnet to receive logging events.
log4net.Appender.TraceAppender Writes logging events to the .NET trace system.
log4net.Appender.UdpAppender Sends logging events as connectionless UDP datagrams to a remote host or a
multicast group using a UdpClient.

Zelf zijn we eigenlijk alleen geïnteresseerd in log4net.Appender.RollingFileAppender en de log4net.Appender.EventLogAppender vanwege bovenstaande voordelen.

Hoe dus te beginnen:

  • Haal de laatste release (versie 1.2.10) van http://logging.apache.org/log4net/download.html.
    Pak de zip ergens uit en onthoud de locatie.
  • Start daarna in Visual Studio een nieuwe console applicatie en maak een referentie naar \log4net-1.2.10\bin\net\2.0\debug\ log4net.dll
  • Schrijf de volgende code en roep de log methode aan in de Main methode:
using log4net;
using log4net.Config;
protected static readonly ILog logger =
 LogManager.GetLogger(typeof(Program));

public static void Log()
{
  XmlConfigurator.Configure();
  logger.Debug("Debug melding REGEL 1/2"
             + Environment.NewLine
             + "Debug melding REGEL 1/2");
  logger.Info("Info melding");
  logger.Warn("Waarschuwing melding");
  logger.Error("FOUT melding");
  logger.Fatal("Fatale melding");
}
  • Voeg een Application Configuration File (app.config) toe aan de applicatie
    en laat deze er zo uitzien:
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net"
             type="log4net.Config.
                    Log4NetConfigurationSectionHandler,Log4net"/>
  </configSections>
  <log4net>
    <root>
      <level value="DEBUG" /> <!-- Overall filter min level -->
      <appender-ref ref="SizeLogFileAppender" />
      <appender-ref ref="DateLogFileAppender" />
      <appender-ref ref="EventLogAppender" />
    </root>
    <appender name="SizeLogFileAppender" type="log4net.
                                   Appender.RollingFileAppender" >
      <param name="File" value="C:\temp\rollingsizelogfile.txt" />
      <param name="AppendToFile" value="true" />
      <rollingStyle value="Date" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="100KB" /> <!-- "10MB" "1GB" -->
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <param name="ConversionPattern"
                     value="%-5p%d{yyyy-MM-dd hh:mm:ss} - %m%n" />
      </layout>
    </appender>
    <appender name="DateLogFileAppender" type="log4net.
                                    Appender.RollingFileAppender">
      <file value="C:\temp\rollingdatelogfile.txt" />
      <appendToFile value="true" />
      <rollingStyle value="Date" />
      <datePattern value="mm" /> <!-- "yyyyMMdd-HHmm" -->
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread]
          %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="WARN" />
        <levelMax value="ERROR" />
      </filter>
    </appender>
    <appender name="EventLogAppender" type="log4net.
                                    Appender.EventLogAppender" >
      <!--<ApplicationName value="MyApp" />-->
      <LogName value="MijnLog" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread]
          %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>
  </log4net>
</configuration>

Hier wordt verwezen naar c:\temp. Deze map zal eventueel aangemaakt worden.
Als je nu de applicatie draait dan worden de logmeldingen in totaal drie keer
opgeslagen. Dit is namelijk beschreven in de root – appender-ref. Dat daar een
level op DEBUG wordt gezet is overigens overbodig (want standaard zo ingesteld) maar hiermee kun je forceren dat je bv. Alleen maar waarschuwingen en erger wilt laten loggen. Vervang DEBUG dan door WARN. Het is dus een filter level geldend voor alle appenders.

De SizeLogFileAppender schrijft voor dat naar een bestand wordt geschreven
waarbij het bestand niet groter dan 100kb mag worden. Normaal zal de limiet veel hoger liggen maar dit is ter demonstratie. Bij overschrijding wordt de naam
uitgebreid met een uniek opeenvolgend getal. Dit getal wordt overigens achteraan in de extensie gezet…

De DateLogFileAppender beschrijft dat afhankelijk van een bepaald overlappend
datumformaat, logmeldingen bij elkaar in één bestand geplaatst worden. Zo wordt hier alle logmeldingen, aangemaakt in dezelfde minuut, bij elkaar gestopt. Als het formaat “yyyyMMdd” was, zou per dag een apart bestand aangemaakt worden.
Overigens is het loggen ook nog eens gefilterd op alleen meldingen van het type
waarschuwing of foutmelding. Andere typen meldingen worden niet toegevoegd.

Als laatste schrijft de EventLogAppender voor dat ook naar de Eventlog wordt
geschreven. Alle logmeldingen worden hierbij niet naar de Application log maar
naar een aparte MijnLog geschreven. Let er op dat LogName niet samen met
ApplicationName wordt gebruikt. In dat geval wordt wel de log aangemaakt maar de meldingen komen toch in de Application log.

In dit voorbeeld wordt geen gebruik gemaakt van logger elementen. Dit geeft
mogelijkheid om appenders abstracter te maken vanuit de code. Hier wordt vanuit de code gewoon de standaard logger aangeroepen (LogManager.GetLogger).

Bovenstaande geeft een aardige aanzet om met Log4Net te kunnen beginnen. Er
is natuurlijk nog veel meer mogelijk maar hier hebben wij voorlopig voldoende
aan. Kijk voor meer informatie op http://logging.apache.org/log4net/release/features.html

Advertenties

Een (b)logitem

Rond logging hangt een heel vreemd sfeertje. Aan de ene kant wordt dit door
iedereen als zeer nuttig ervaren en wil iedereen allerhande informatie loggen om
zeer uiteenlopende redenen.

Ontwikkelaars willen de interne werking ontsluiten daar waar ze geen
compiler mogen installeren om door de code te steppen. Projectleiders
willen graag inzicht in het aantal bugs en storingen die tijdens de testfase en
productie optreden. Het afdelinghoofd wil graag weten welke gebruiker door
roekeloos gebruik de helft van de administratie verwijderd heeft. Gebruikers
willen graag dat door hen ondervonden vage problemen bevestigd worden met
meldingen in de log en systeembeheer wil graag de gezondheid van de ‘vijandige’
applicaties op hun trouwe servers meten. Kortom, Logging moet staan als een
huis, ahum, Log..

.Log voorafgaande aan het computertijdperk

Maar aan de andere kant is logging een sluitpost tijdens de bouw, test en
productiegang. Het mag geen performance kosten, het moet amper ruimte op de
server consumeren, de eventlog mag niet vervuild worden en de berichten moeten vooral bondig zijn om niet teveel bedrijfsinformatie prijs te geven.

Kortom, met logging is het wat treurig gesteld.

Gelukkig heft het probleem zichzelf snel op zodra de eerste uitrol naar de
testserver gedaan is. De ontwikkelaars verliezen bijna de totale controle over
de applicatie, kunnen geen uitspraak doen bij vage en minder vage problemen en
opeens staat logging weer hoog op hun verlanglijstje.

In een ontwikkelstraat is logging meestal al wel goed geregeld met een eigen
architectuur en in een SOA omgeving zal het zelfs onderdeel van het totale
systeem zijn. Hierbij kunnen berichten over de bus een prima indicatie geven
over de voortgang en werking. En puristen zullen met Aspect Oriented Programming (AOP) aan de slag gaan.

Maar als je niet in deze ‘luxe’ positie bent dan zal je zelf voor de logging
moeten zorgen. Natuurlijk is er de Enterprise library van Microsoft. Dit geeft gelijk een goede basis voor andere basis onderdelen van een gemiddeld systeem zoals data access, cryptografie, caching, exception handling en security.

Maar wil je een lichtere variant dan kan je eens kijken naar Trace listeners.
Hierbij is het loggen zeer eenvoudig. Eerst geef je in de app.config (of
web.config) een opsomming van de gewenste manier van loggen (bv. tekst bestand, Xml, CSV, eventlog) op. Daarna is een aanroep van b.v. Trace.WriteLine(“….”); voldoende. Dit is dus logging implementeren in enkele minuten en refactoren is een eitje. Overigens, waar in de functionele requirements stond de tekst over de implementatie van logging ook al weer? Dus wie maakt je wat?

Hieronder zijn de standaard aanwezige tracelisteners opgesomd welke in het
.Net framework al meegeleverd worden:

Trace listener Gebruik
System.Diagnostics.DelimitedListTraceListener Schrijft meldingen in een CSV formaat
System.Diagnostics.XmlWriterTraceListener Schrijft meldingen in een XML formaat
System.Diagnostics.EventLogTraceListener Stuurt meldingen naar de eventlog
System.Diagnostics.TextWriterTraceListener Schrijft meldingen in een tekstbestand zonder formattering
Microsoft.VisualBasic.Logging.FileLogTraceListener Schrijft meldingen telkens in een nieuw tekstbestand op bv. dagelijkse
basis
System.Web.WebPageTraceListener Schrijft meldingen als trace bij de webpagina
System.Diagnostics.ConsoleTraceListener Schrijft meldingen als standaard output

Vooral de EventLogTracelistener en de FileLogTraceListener zijn interessant.
De eerste kan (niet verwonderlijk) naar de eventlog loggen. Let er wel op dat
hier eventueel extra rechten voor nodig zijn. Ook logt deze direct in
Application log.

Vrijwel iedereen start met het loggen in TextWriterTraceListener terwijl deze
een veel interessanter zusje in de Visual Basic hoek van het framework heeft.
Anders dan haar broertje kan de log netjes per dag opgedeeld worden en
daardoor staat er geen unieke lock op het de totale log. Vooral systeembeheer
vind dit heel prettig… want dan kan de log weer snel verwijderd worden. Maar
voor een C# ontwikkelaar is het even slikken want hij is overgeleverd aan die
dekselse VB.Net 😉 En deze listener is een aardig alternatief voor de grote
broer, de Rolling Flat File Trace Listener uit de Enterprise Library.

Heb je jouw keuze kunnen maken? Ga dan door naar de volgende stap. Neem in
het configuratiebestand een SharedListeners sectie op. Hieronder is een hele
lijst opgesomd. Dit is indicatief, er wordt namelijk niet direct naar al de
genoemde listeners geschreven. Slechts diegene die ook genoemd worden in de
listeners sectie, zullen ook daadwerkelijk aangesproken gaan worden. Hiermee
wordt het dus eenvoudig om zonder een regel code aan te passen, te wisselen van
log.

<?xml version="1.0" encoding="utf-8" ?><configuration>
 <system.diagnostics>
  <sharedListeners>
   <add name="MyDelimitedListTraceListener"
        type="System.Diagnostics.DelimitedListTraceListener"
        delimiter=":"
        initializeData="c:\temp\MyDelimitedListTraceListener.txt"
        traceOutputOptions="ProcessId, DateTime" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
   <add name="MyXmlWriterTraceListener"
        type="System.Diagnostics.XmlWriterTraceListener"
        initializeData="c:\temp\MyXmlWriterTraceListener.xml"
        traceOutputOptions="ProcessId, DateTime" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
   <add name="MyEventLogTraceListener"
        type="System.Diagnostics.EventLogTraceListener"
        initializeData="MijnEigenTestLog"
        source="MijnTraceEventLog" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Warning" />
   </add>
   <add name="MyFileLogTraceListener"
        type="Microsoft.VisualBasic.Logging.FileLogTraceListener,
        Microsoft.VisualBasic, Version=8.0.0.0, Culture=neutral,
        PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL"
        initializeData="FileLogWriter"
        basefilename="MyFileLogName"
        autoflush="true"
        logfilecreationschedule="Daily"
        location="Custom"
        customlocation="c:/temp/" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
   <add name="MyVerboseTextWriterTraceListener"
        type="System.Diagnostics.TextWriterTraceListener"
        initializeData="c:\temp\MyTextWriterTraceListener.log">
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
   <add name="MyErrorTextWriterTraceListener"
        type="System.Diagnostics.TextWriterTraceListener"
        initializeData="c:\temp\MyTextWriterTraceListener.log">
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Error" />
   </add>
   <add name="MyWebPageTraceListener"
        type="System.Web.WebPageTraceListener, System.Web" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
   <add name="MyConsoleListener"
        type="System.Diagnostics.ConsoleTraceListener" >
    <filter type="System.Diagnostics.EventTypeFilter"
            initializeData="Verbose" />
   </add>
  </sharedListeners>
  <trace autoflush="true">
   <listeners>
    <remove name="Default"/>
    <add name="MyFileLogTraceListener"/>
    <add name="MyEventLogTraceListener"/>
   </listeners>
  </trace>
 </system.diagnostics>
</configuration>

Wellicht is het ook opgevallen dat bij de listener een filter mogelijkheid
wordt opgegeven. Dit wordt ook wel het Trace Level genoemd. De Trace class geeft namelijk de mogelijkheid om logmeldingen van een typering te voorzien.
Foutmeldingen en waarschuwingen spreken voor zich. Het verschil tussen de
typeringen Verbose en Information zijn minder opzichting. Ik hou altijd de
vuistregel aan dat op productie alleen waarschuwingen en foutmeldingen getoond moeten worden. Information gebruik ik om gedrag en interne keuzes zichtbaar te maken en dit moet zo beperkt mogelijk. Maar voor alle overige meldingen gebruik ik Verbose, en dat kan best ver gaan. Zo is het een prima gebruik om bij het starten van een applicatie de totale config als verbose te loggen. Dit geeft goed aan onder welke randvoorwaarden de applicatie moet draaien.

Hierdoor zullen de logbestanden tijdens de ontwikkel en testfase best
uitdijen maar hiermee kan heel veel informatie ingewonnen worden om ongewenst gedrag te analyseren.

Trace level instelling Wat wordt er dan gelogd?
Verbose Alle soorten meldingen
Information Ter zake doende informatie, waarschuwingen en foutmeldingen
Warning Slechts waarschuwingen en foutmeldingen
Error Alleen foutmeldingen
None Tja..

Op productie zie je dus meestal het Trace Level op Warning ingesteld zien
staan.

Hoe maak je dan het onderscheid tussen de verschillende boodschappen die je
wilt loggen? De Trace class heeft hiervoor een aantal verschillende methodes en
in onderstaande Log class is dit nog eens vereenvoudigd met slechts 1 methode.
Zoals alles in computerland zijn alle problemen op te lossen met slechts 1 laag
van abstractie dus later kan onder de class best een andere manier van loggen
gehangen worden.

/// <summary>/// Class voor het wrappen van en loggen via TraceListeners/// </summary>
public static class Log
{
 /// <summary>
 /// Log een melding.
 /// </summary>
 /// <param name="category">een categorie.</param>
 /// <param name="messageText">de boodschap.</param>
 /// <param name="traceLevel">Opgegeven level bij de boodschap.</param>
 /// <exception cref="System.NotImplementedException">
///  Melding als de doorgegeven Traceswitch niet ondersteund wordt
/// </exception>
 public static void LogTraceMessage( string category,
                        string messageText, TraceLevel traceLevel)
 {
  string tekst = category.PadRight(20) + "- " +
    messageText.PadRight(50) + " at " +
    DateTime.Now.ToString(CultureInfo.CurrentCulture);
  switch (traceLevel)
  {
   case TraceLevel.Verbose:
   {
    Trace.WriteLine(tekst, category);
    return;
   }
   case TraceLevel.Info:
   {
    Trace.TraceInformation(tekst, category);
    return;
   }
   case TraceLevel.Warning:
   {
    Trace.TraceWarning(tekst, category);
    return;
   }
   case TraceLevel.Error:
   {
    Trace.TraceError(tekst, category);
    return;
   }
   case TraceLevel.Off:
   {
    return;
   }
   default:
   {
    throw new NotImplementedException("Onbekende tracelevel");
   }
  }
 }
}

Kortom, nu is het mogelijk om op een eenvoudige en snelle manier logging te
introduceren.

Mocht het hier bescheven lijstje van listeners niet aan de wensen voldoen en
is de overstap naar een ander logging framework ook niet van toepassing, dan kun je nog altijd jouw eigen tracelistener overerving schrijven. Dit is redelijk
trivial. Het enige wat gedaan moet worden, is het implementeren van twee
overerfde methodes (Write en WriteLine) om b.v. met een SMS te loggen. Neem
daarna de assembly met de overerfde SmsTraceListener op in de configuratie en
het loggen gaat beginnen.

Loggen kan nu nooit meer een sluitpost zijn.