Soms, als er iets verkeerd gaat en het enige dat je hebt is een stack trace, zou je graag wat meer informatie willen hebben over de stappen die naar het probleem leiden. Het aanzetten van debug logging kan leiden tot een enorme hoeveelheid gegevens die worden gelogd voordat de fout opnieuw optreedt. Het zou handig zijn als de debug informatie alleen zou worden gelogd kort voordat de fout optreedt en verder wordt genegeerd. Met BackTraceAppender [1], een op maat Log4J appender, is dit mogelijk.

Dit artikel beschrijft hoe BackTraceAppender te gebruiken, hoe deze is geïmplementeerd als een voorbeeld van het creëren van een Log4J appender en enkele nadelen bij het gebruik en mogelijke alternatieven. Enige ervaring met Log4J [2] is noodzakelijk.

Gebruik

BackTraceAppender kan worden gebruikt door het plaatsen van backtraceappender-0.1jar [3] op het classpath en het toevoegen van een appender in het log4j configuratie bestand. De backtrace appender is geïmplementeerd als een AppenderAttachable, een log4j interface die fungeert als een soort filter die voor concrete appenders gezet kan worden. Het kan worden gebruikt in combinatie met andere appenders, zoals ConsoleAppender. Dit maakt het meer flexibel maar ook iets moeilijker om te configureren, omdat dit in twee stappen moet gebeuren:

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">
 
  <appender name="ConsoleAppender" 
            class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" 
             value="&lt;%d &gt; &lt;%p&gt; %m%n"/>
    </layout>	
  </appender>
 
  <appender name="BackTraceAppender" 
            class="com.meulengraaf.log4j.BackTraceAppender">
    <param name="Size" value="128"/>
    <param name="Order" value="LIFO"/>
    <param name="TriggerLevel" value="ERROR"/>
    <appender-ref ref="ConsoleAppender"/>
  </appender>
 
  <root>
    <level value="DEBUG"/>	  
    <appender-ref ref="BackTraceAppender"/>
  </root> 
 
</log4j:configuration>

Dit voorbeeld van een log4j configuratie creëert een BackTraceAppender dat een ConsoleAppender gebruikt welke de feitelijke logging uitvoert. Het maximale aantal regels met debug logging wordt geregeld door de “Size�? parameter. De “Order�? bepaalt de volgorde waarin de debug informatie zal worden gelogd, óf First-In-First-Out óf Last-In-First-Out. De laatstgenoemde is gewoonlijk het meest bruikbaar. “Appender-Ref�? wordt gebruikt om te refereren aan de werkelijke appender: in dit geval een ConsoleAppender.

Een handige optie is de speciale BackTraceFileAppender. Deze appender schrijft iedere fout naar een uniek bestand samen met de debug regels die naar de fout leidden:

<appender name="BackTraceFileAppender"     
          class="com.meulengraaf.log4j.BackTraceFileAppender">
  <param name="File" value="error-%uid.log"/>
  <param name="Append" value="true"/>
  <param name="UidGenerator"  
         value="com.meulengraaf.log4j.SimpleUidGenerator"/>
  <layout class="org.apache.log4j.PatternLayout">
    <param name="ConversionPattern" 
           value="&lt;%d &gt; &lt;%p&gt; %m%n"/>
  </layout>	
</appender>

Dit definieert een BackTraceFileAppender. Het is feitelijk een normale file appender met de mogelijkheid om een unieke naam per fout te genereren. Dit wordt gedefinieerd door de “%uid�? variabele in het “File�? kenmerk en met “UidGenerator�?, dat dit unieke id genereert. De generator in dit voorbeeld voegt alleen een nummer toe aan de bestandsnaam. Het is eenvoudig om je eigen generator te schrijven.

Denk er aan dat we het root level (of wat we ook willen loggen) op “DEBUG�? zetten of welk level dan ook dat we willen gebruiken voor de backtrace. Let ook op dat we “Threshold�? niet op een niveau zetten in de ConsoleAppender dat de debug logging zou weg filteren.

Implementatie

BackTraceAppender overerft van AppenderSkeleton en implementeert de AppenderAttachable interface. Beide zijn van de Log4J API en bedoelt voor het maken van je eigen logging appenders. Implementeren van de AppenderAttachable interface betekent dat je er andere appenders aan kunt koppelen. Het fungeert dan als een soort filter voor een andere appender. Dit verlangt echter wel meer configuratie omdat zowel de te verbinden appender als de concrete appender moeten worden beschreven.

AppenderSkeleton is een abstracte base class en levert de meeste boilerplate code van een appender. Zie [4] voor de volledige sources en configuratie files. Het belangrijkst is de append method, deze moet in de BackTraceAppender subclass worden vervangen. Wanneer een logging event wordt genereert zal deze niet direct door Log4J naar een appender worden verstuurd maar het zal eerst in een queue geplaatst worden. Als het logging event een niveau error of hoger heeft zal de hele queue naar alle aangesloten appenders samen met het error event verstuurd worden. Als de queue vol is zal het oudste logging event worden verwijderd. De queue zelf is gedefinieerd als een thread local variabele; deze is alleen bekend bij de actieve thread. Zodra de thread afgesloten wordt, zal de thread local queue ook worden verwijderd. Zie [5] voor een interessant artikel over thread local variables.

public void append(LoggingEvent event) {
    LoggingEventQueue list = threadLocalStack.getList();
    list.push(event);
    if (event.getLevel().isGreaterOrEqual(triggerLevel)) {
        appendLoopOnAppenders(list.popAll());
    }
}

Indien één van de aangesloten appenders de BackTraceable interface implementeert zal het een rollover activeren, zodat het een nieuw file zal creëren voor de volgende fout.

private void appendLoopOnAppenders(LoggingEvent[] list) {
    for (Iterator iter = appenders.iterator(); iter.hasNext();) {
        Appender appender = (Appender) iter.next();
        for (int i = 0; i < list.length; i++) {
            appender.doAppend(list[i]);
        }
        if (appender instanceof BackTraceable) {
            ((BackTraceable) appender).rollOver();
        }
    }
}

De BackTraceable interface geeft alleen aan dat de appender een rollover accepteert van buitenaf. De BackTraceFileAppender implementeert deze interface zodat het een nieuwe file kan creëren met een unieke naam voor elke back trace gebeurtenis. De meeste logica om een file als output te gebruiken komt van de FileAppender class uit de Log4J API.

Nadelen en alternatieven

Het gebruik van deze back trace appender zal extra geheugen kosten. Als de gemiddelde log message 80 bytes is en we hebben een queue van 128 zou dit 128 * 80 / 1024 = 10K per thread betekenen. Bij gebruik van veel threads kan dit aanzienlijk oplopen. Natuurlijk moeten we ook debug level aanzetten, anders wordt er niets als backtrace opgeslagen. Disk IO zal echter een stuk minder zijn doordat de debug informatie alleen naar disk zal worden geschreven indien een fout optreedt.

Andere interessante trace opties zijn aspects en Dtrace. Met aspects kan je overal debug code invoegen zonder de source code zelf aan te passen. Er zijn veel voorbeelden te vinden voor deze aanpak. Met Dtrace [6] van Sun hoef je dit zelfs niet meer te doen, je kan dynamisch iedere class of method traceren in de draaiende code. DTrace is echter alleen beschikbaar voor Solaris 10 en OpenSolaris.

Conclusie

Dit artikel laat zien dat het eenvoudig is om je eigen op maat log appender te creëren voor Log4J. BackTraceAppender kan gebruikt worden om bugs te vinden die alleen af en toe optreden en niet makkelijk gereproduceerd kunnen worden. De hoeveelheid log informatie zal enorm afnemen vergeleken met de traditionele manier van logging waar gewoon alles wordt gelogd.

Resources

[1] BackTraceAppender for Log4J
[2] Log4j project homepage
[3] BackTraceAppender library
[4] BackTraceAppender sources
[5] Threading lightly, Part 3: Sometimes it’s best not to share
[6] DTrace and Java Technology: Understanding the Application and the Entire Stack
[7] Finalist IT Group

Auteur: Rob van de Meulengraaf - Java Developer at Finalist IT Group [7]
Vertaling: Wilma Noordam
Review: Erik van Oosten