Programare Java - utilizare log4j

Programare Java - utilizare log4j pentru începători
- pentru programatori -

Pe scurt : log4j este o bibliotecă de logging/trace larg utilizată în Java. Se foloseşte pentru a afişa din program mesaje, într-un mod uniform şi customizabil, automatizînd operaţiile redundante (de ex. afişarea datei la fiecare mesaj). O puteţi obţine de la https://logging.apache.org/log4j/

Scop
 Acest articol se doreşte o introducere în log4j. Log4j este doar una din bibliotecile de logging Java existente, dar este printre cele mai folosite. Despre logging/trace în general, alegerea nivelului de trace şi "best practice" la logging am vorbit într-un articol mai vechi, arătând cum se poate face o bibliotecă simplă de logging.

Introducere rapidă în log4j


Pentru a folosi log4j, în fiecare clasă se declară un membru:
private final static Logger log = Logger.getLogger( NumeClasa.class );



Logurile se vor trimite cu:
log.fatal( "Eroare fatală, programul se termină");
log.error( "Eroare gravă (ex. excepţie?), dar programul poate continua");
log.warn( "Situaţie neobişnuită, ar putea însemna o problemă");
log.info( "O informaţie pentru ochiul utilizatorului (suficient de rar)");
log.debug( "O informaţie mai detaliată pentru depanarea unor probleme de către utilizator");
log.trace( "O informaţie pentru depanarea programului de către programator");

Note :
 - static asigură că se va crea un singur log pentru toate obiectele de tip NumeClasa (economiseşte memorie)
- final poate aduce un mic avantaj de performanţă în programe multithreading (economiseşte CPU)
- private este natural, nu avem de ce să folosim acest log din altă clasă
- NumeClasa.class în loc de stringul "NumeClasa" asigură faptul că la schimbarea numelui clasei se va modifica şi numele declarat la logger.

Pentru a funcţiona log4j, va trebui inclus în fiecare clasă pachetul respectiv:
import org.apache.log4j.Logger;

Atenţie să nu importaţi din greseală loggerul inclus în JRE-ul java (java.util.logging), care este similar dar are mult mai puţine facilităţi

Mai trebuie adăugat în classpath biblioteca log4j, ceva de genul :
log4j-1.2.14.jar


Avantaje log4j
Deşi mai laborios de folosit decât varianta cu metode statice, log4j aduce câteva avantaje, în special la proiecte medii/mari:

  • nivelul de log poate fi setat separat la fiecare clasă. Adică pot seta nivel INFO ca default, apoi pot seta nivelul DEBUG sau TRACE pentru clasa sau ierarhia de clase la care fac depanare.
  • Nici nu trebuie să modific acea clasă sau jar-ul, totul se poate seta exterior, modificând fisierul de configurare log4j.xml
  • Formatul logului se poate seta şi el la rulare, tot în log4j.xml
  • La nevoie (dar nerecomandat) se poate seta nivelul de log şi din program, de exemplu în funcţia main() cu: Logger.getLogger("").setLevel(Level.DEBUG);
  • Dacă foloseşti anumite bilioteci (apache.org mai ales), ele vor loga oricum folosind log4j. Este mai convenabil să foloseşti tot log4j decât să foloseşti 2 sisteme diferite, cu configurări diferite
  • log4j permite trimiterea logurilor la mai multe "appendere", eventual cu nivel de logging diferit. De exemplu afişez pe ecran la nivel INFO, iar în fişier loghez pe nivel DEBUG (mai detaliat)
Configurare log4j

Pentru a configura log4j trebuie creat un fişier log4j.xml, în care se defineşte nivelul de log pentru fiecare subarbore de clase şi nivelul default. Pentru a referi un subarbore de clase se scrie prefixul pachetului. De asemenea se definesc mai multe appendere, care definesc unde se duc logurile (ecran, fişier) şi formatul în care se face logging.

Exemplu log4j.xml:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'>
    <appender name="defaultAppender" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
              <param name="ConversionPattern" value="%d %-5p [%-4t] %m (%F:%L)%n"/>
             <!--   <param name="ConversionPattern" value="%-4r [%t] %-5p %c %x - %m%n" /> -->
             <!--   <param name="ConversionPattern" value="%c: %d %-5p [%-4t] %m (%F:%L)%n"/> -->
                <!-- <param name="ConversionPattern" value="%d %X{user} %X{requestId} %-5p [%-4t] %m (%F:%L)%n"/> -->
              <!--  <param name="ConversionPattern" value="%d %-5p [%-4t] %m %n"/>   -->
        </layout>
    </appender>
    <root>
        <level value="debug" />
        <appender-ref ref="defaultAppender" />
    </root>
</log4j:configuration>


Textul de mai sus trebuie pus într-un fişier numit log4j.xml iar acesta trebuie pus undeva în classpath. Se poate pune în ./src/ (rădăcina arborescenţei de clase), dar o idee mai bună este să se pună într-un director separat (exemplu "./ressources") care să fie inclus apoi în classpath. Acest director poate să rămână astfel în afara jar-ului aplicaţiei, putând fi customizat fără a reface arhiva jar. Atenţie, dacă arhiva jar are "MANIFEST", trebuie să fie adăugat şi directorul "./ressources" în linia "Class-Path:" din META-INF/MANIFEST.MF.

Formatul logului log4j
Am folosit ca pattern de afişare la ConversionPattern : "%d %-5p [%-4t] %m (%F:%L)%n". Rezultatul este ca mai jos:

2011-06-05 23:13:38,975 INFO [main] Detected local ip=192.168.101.101 (MyClass.java:224)
Explicaţie:
%d reprezintă data - foarte importantă la depanare ulterioară, se poate observa ce durează mult
%-5p reprezintă nivelul de log (aici INFO), pe minim 5 caractere - ajuta la aliniere
[%-4t] reprezintă numele threadului, pe minim 4 caractere. Important la aplicaţii multithreading
%m reprezintă mesajul propriu zis
(%F:%L) reprezintă numele fişierului şi linia de unde s-a trimis logul. Foarte util pentru depanare. În Eclipse, un simplu click pe log te duce la locul în care s-a dat logul cu problemă
%n face trecerea la o nouă linie

Atenţie, opţiunile de afişare a fişierului şi liniei consumă mult mai mult procesor decât fără, dar nu ar trebui să vă faceţi probleme dacă daţi sub 100 loguri pe secundă. Puteţi oricând dezactiva afişarea fişieruli la rulare.

Depanare log4j

De multe ori nu este clar de unde îşi ia log4j fişierul de configuraţie. Dacă există mai multe, îl ia pe primul pe care îl găseşte, care poate fi altul decât ne aşteptăm. Poate găsi log4j.xml într-o bibliotecă jar de exemplu - de aceea nu este politicos să punem log4j.xml în jar-uri. Locul din care este luat fişierul jar şi alte detalii despre iniţializare se pot obţine setând o opţiune specifică la pornirea maşinii virtuale java. După setare, programul va afişa verbose detalii despre iniţializarea log4j.
java -Dlog4j.debug=true ....

În Eclipse, opţiunea "-Dlog4j.debug=true" se poate pune la "VM arguments" din configuraţia de "Run".

Opţiuni avansate log4j
Atunci când programul execută mai multe cereri în paralel (pe mai multe threaduri paralele), este util să ştim la care cerere se referă fiecare linie de log.

O abordare mai naivă dar utilă ar fi să redenumim numele threadului cu identificatorul cererii, astfel vom putea grupa după numele threadului logurile care se refera la aceeaşi cerere. Dezavantajul este ca trebuie redenumit threadul la fiecare nouă cerere şi la fiecare subthread.

O abordare mai flexibilă este folosirea facilităţii MDC (Mapped Diagnostic Context). Prin MDC, log4j poate ataşa fiecărui thread nişte etichere (nume=valoare), etichete care se menţin pe durata threadului şi se moştenesc şi la threadurile copil. Folosind o configurare log4j poate pot afişa valoarile unor chei setate cu MDC.

Exemplu:
La primirea cererii cu număruil 1234 de la userul "gigel", se poate apela o funcţie statică log4j:

MDC.put("requestId", "1234");
MDC.put("user", "gigel");

Dacă în configuraţia appenderului log4j exista patternul "%X{requestId}", valoarea setată (1234) se va afişa în log la poziţia respectivă. Dacă există patternul "%X{user}", se va afişă în acel loc "gigel".

Configuraţie : <param name="ConversionPattern" value="%d user=%X{user} request=%X{requestId} %-5p [%-4t] %m (%F:%L)%n"/>

Nu am folosit foarte mult această facilitate, dar mi se pare foarte utilă, aşa că am reprodus-o din memorie, sper că şi corect. Rog semnalaţi eventuale erori.

[Notă: acest articol a fost scris în 2010 sau 2011 ca și continuare la acesta, dar am uitat să-l public, probabil intenționam să-l îmbunătățesc; poate ajută totuși pe cineva...]