Traceuri/Loguri in Java

 Îndrumar folosire trace-uri / log-uri in Java

- articol pentru programatori -

 Pe scurt: aproape orice program merită să aibă un sistem centralizat de trace-uri/log-uri, de exemplu log4j. Nivelele de trace se aleg astfel :

•  FATAL : eroare gravă, programul nu mai poate continua, urmează exit(-1). SLF4J recomanda folosirea tot a nivelului ERROR în acest caz.

•  ERROR : eroare gravă, "așa ceva nu trebuia să se întâmple"

•  WARNING : semnalează o posibilă eroare, dar care poate fi comportament normal în unele cazuri

•  INFO : afişeaza informaţii utile pentru utilizatorul programului. Nivelul nu trebuie să fie prea verbose, trebuie să poată fi citit de un utilizator uman indiferent de volulumul inputului.

•  DEBUG : dă informații utile programatorului aplicaţiei în cazul în care apar probleme de funcţionare. Este echivalent cu "verbose".

•  TRACE : dă informații foarte detaliate despre fiecare pas important al programului (util în depanarea de către programator). Pentru că pe nivelul TRACE pot fi foarte multe loguri, trace-urile pot consuma foarte mult procesor chiar dacă nu sunt afișate. Cauza este faptul că stringul de afișat se calculează chiar dacă nu va fi afișat. Performanța se poate ameliora testând întâi nivelul de trace înainte de face apelul de log. Alte loggere (SLF4J) permit trimiterea obiectelor separat, urmând a fi evaluate (.toString()) doar dacă trebuie afișate.

P.S. : am modificat căteva lucruri pe măsură ce mi-a crescut experiența : adăugat nivel TRACE, mutat unele loguri de la INFO la DEBUG și de la DEBUG la TRACE. Nu am refăcut restul textului cu noua abordate.


Introducere

   Am scris mai demult un articol despre excepții în Java. O sa prezint acum câteva concluzii la care am ajuns despre folosirea trace-urilor/logurilor în general și cu aplicații în limbajul de programare Java.

Ce sunt trace-urile ?

  Realitatea este ca programele au bug-uri. Mai devreme sau mai târziu vom fi nevoiți să cercetăm de ce programul nu funcționează așa cum speram într-un anumit caz. Pentru asta avem nevoie de informații despre execuția programului, ce probleme a întâmpinat, ce s-a executat cu success si ce nu.

 

  Trace-urile sunt linii de text emise de un program care "povestesc" pașii importanți prin care trece programul. Dupa cum le spune și numele, trace-urile sunt niște "urme" care ramân în ... urma executării programului.

 De exemplu trace-urile conțin informații despre erori, situații deosebite, unde a ajuns programul cu o anumită activitate mai lungă. Trace-urile sunt un feedback util, putem să vedem că programul incă rulează chiar dacă nu poate scoate incă un output util.

 Linia de trace conţine de obicei data si nivelul de trace, si opţional threadul si fisierul/linia de la care provin. Fisierul şi linia sunt foarte utile în identificarea problemei. Rulând programul in Eclipse si făcând click pe (fisier:linie), editorul ajunge exact la linia respectivă, ceea ce optimizează mult depanarea.


2010-06-01 12:09:56,582 WARN    [main] ApplicationConfig not ready (AdsManager.java:414)
2010-06-01 12:09:56,584 DEBUG  [main] HttpClient created with maxTotalConnections=20 (AdsManager.java:418)
2010-06-01 12:09:56,584 INFO     [main] Initializating with CachePath="/cache/" (AdsManager.java:380)

Trace-urile pot fi emise direct pe ecran sau pot fi scrise intr-un fisier de "log". Trace-urile scrise pe ecran (consolă) pot fi si ele redirectate intr-un fisier de către utilizator. Se recomandă emiterea trace-urile pe "standard error" ( System.err.println() ), pentru a putea fi separate de outputul "util" al programului care va ieşi pe "standard output".

 Trace-urile nu trebuiesc confundate cu rularea "pas-cu-pas" a programului dintr-un program "debugger". Spre deosebire de debuger, trace-urile nu întrerup  funcţionarea programului. La modul ideal, trimiterea trace-urilor ar trebui să aibă un impact cât mai mic în încetinirea programului, dar pentru asta este necesară puțina atenție.

 Trace-uri, log-uri sau alarme ?

 Eu prefer să numesc trace-uri informatiile care folosesc la monitorizarea și depanarea programului. Anumite programe specializate ar putea să aibă alături de trace-uri un sistem paralel de log-uri. Log-urile sunt pentru mine nişte informaţii mai puţin legate de program ci de datele procesate. 

 De exemplu anumite aplicatii de telefonie pot "log-a" fiecare apel telefonic pentru a calcula factura pe baza lor la sfarșitul lunii. De obicei log-urile au un format mai strict decăt trace-urile. Log-urile sunt menite sa fie procesate automat iar trace-urile sunt destinate in special ochiului uman. Veti intâlni  adeseori ambele denumiri ca fiind echivalente.

 Alarmele sunt niste trace-uri active, care anunță un server de monitorizare despre evenimente speciale din timpul executiei unui program, de exemplu pornirea, oprirea, erori intâlnite. In cazul sistemelor critice, serverul de monitorizare are de obicei o persoană care supraveghează permanent alarmele, le investighează si ia măsuri de remediere când este cazul.

Trace-urile obișnuite sunt de obicei pasive, ele sunt verificate doar cănd administratorul programului vrea niște informații suplimentare.

  Cum folosim trace-urile ?

  Sistemul clasic de trace-uri folosește câteva nivele distincte de trace, in funcție de importanță/gravitate (exemplu FATAL, ERROR, WARNING, INFO, DEBUG). Cele mai grave evenimente sunt erorile fatale, iar cele mai putin importante sunt informațiile detaliate despre paşii prin care trece programul.

In funcție de necesități, administratorul poate alege să vadă doar trace-urile care depașesc o anumită gravitate, de exemplu doar erorile sau doar erorile si warning-urile (avertizările). In cazul în care se depanează programul, se poate activa nivelul maxim de trace-uri, care va trimite cât mai multe informații posibile.

Este important ca programul să aibă trace-uri pentru fiecare pas mai mare pe care îl face. Programul trebuie să poată fi configurat la rulare să trimită doar trace-urile peste o anumită gravitate, pentru a nu consuma resurse inutile atunci când nu sunt necesare trace-urile detaliate. 

Sistemele avansate de trace pot activa nivele de trace diferite pe diferite module  de interes, pentru a obtine cel mai bun compromis intre informații si performanță. Un logger profesionist poate fi configurat să trimită logurile în mai multe locuri (consolă si fisier, pe alt server, etc)

Este mai simplu dacă sistemul de trace are si o metodă de afişare a excepţiilor, cu un apel de genul log.error("Unexpected exception : ", e);

Nivelele de trace pe larg

•  FATAL (unrecoverable) : este trimis când programul a înâlnit o eroare foarte gravă, la care trebuie să se oprească. De exemplu programul nu poate să aloce memorie, nu poate deschide un fisier de input etc. Dupa ce trimite trace-ul FATAL, de obicei programul face exit(-1). Mesajul trebuie să contină o descriere cât mai clară a motivului care a determinat programul să se oprească anormal. Daca cauza poate fi înlăturată de utilizator, se prezintă acestuia posibile soluții. Daca cauza este o exceptie "this should never happen" (cauzată de un bug)  atunci se printează obligatoriu stack-ul pentru a fi reprodusă/depanată de programator.

• ERROR (recoverable) : este emis când programul a întâlnit o eroare gravă, dar poate totuşi continua. Daca problema este externă (a picat conexiunea la baza de date) se da un mesaj pentru utilizator cu contextul problemei (server, user, tabel). Daca eroarea provine de la o problemă de programare se printează stack-ul pentru programator.

• WARNING (posibilă problemă) : este emis cănd programul a întălnit o situatie neobișnuită sau posibilă eroare care totuși ar putea fi normală în anumite cazuri. De exemplu utilizatorul a restartat baza de date, programul a trebuit să se reconecteze. Utilizatorul poate decide dacă situația este normală sau nu. De obicei nu se printează stack-ul intrucăt problema nu este neașteptată - daca ar fi neașteptată nu am știi că "ar putea fi normală în anumite cazuri" si ar fi "ERROR"
  

• INFO (verbose) : pe acest nivel sunt semnalate informații utile utilizatorului software-ului, de exemplu operatorilor de support. Pe acest nivel se dau informatii statistice despre rularea programului, se pot semnala inceputul/sfarşitul anumitor operaţii. Se poate chiar afişa fiecare cerere şi răspuns al unui sistem, cu condiţia ca acestea să nu fie prea multe, altfel afectează performanţa. Din experienţa mea 100 requesturi/secundă pot fi logate fără un impact de performanță notabil.

• DEBUG (depanare) : pe acest nivel se dau informatii pentru a se face depanare de catre un programator. La limită, fiecare funcție importantă poate avea un trace pe nivel debug cu inputul si output-ul său. Alte informatii utile unei eventuale depanări pot fi incluse pe parcursul funcției. Procesarea unui singur request poate genera mii de linii de DEBUG, dar de obicei rularea programului pe nivel DEBUG poate afecta performanţa, incetinind programul. Trace-urile care se efectuează de peste 1000 ori pe secundă ar putea să încetinească programul chiar dacă nivelul de trace nu este pe DEBUG. Detalii mai jos.

Exepţii de la regulă (gravitate versus importantă)

De fapt există cel puţin doua axe pe care se pot clasifica evenimentele, gravitate şi importantă. De exemplu unele mesaje sunt importante (versiunea programului, faptul că a pornit si s-a oprit la o anumită oră), dar nu sunt şi grave. Clasificarea pe o singură axă a gravitătii poate să nu fie suficientă, de aceea eu fac anumite exceptii de la regula gravitătii.

In principiu este de dorit să existe versiunea si parametrii programului in orice log, pentru a uşura depanarea. Aceste informaţii ar apartine de nivelul INFO, dar eu prefer să le dau pe nivelul WARNING pentru a le avea în trace şi atunci cănd programul rulează în mod "ne-verbose". Includ în textul mesajului un "[INFO]" pentru a preciza că nu este de fapt decăt o informaţie, chiar dacă apare pe nivel "WARNING".

Nivelul normal de rulare (ne-verbose) al unui program ar trebui sa fie WARNING. Aceste loguri ar trebui să fie suficient de rare incât să poată să "sară in ochi" utilizatorului cănd se intămplă ceva ciudat. Pe nivelul INFO sunt de obicei prea multe informaţii, utilizatorul ne-urmărindu-le decăt dacă caută ceva anume.

Alte informaţii care ar aparţine nivelului INFO dar am preferat să le dau pe nivel WARNING erau informaţii la 20-30 secunde despre încărcarea sistemului (numar de utilizatori, memorie consumată, număr de operaţii pe secundă.

Probleme de performanţă la trace-uri/log-uri


La fiecare apel al unui trace, se consuma un pic de timp. Un trace care afişeaza maxim 100 linii pe secundă nu are de obicei un impact de performanţa, peste 1000 linii pe secundă ar putea să incetinească programul, dupa caz.


Dacă trace-ul este sub nivelul de afişare se execută doar condiţia if(nivel < traceLevel). Procesoarele moderne pot executa sute de milioane de comparaţii pe secundă, deci asta nu consumă foarte mult din CPU. In Java am obtinut 250 milioane comparaţii/secundă pe un sistem 2*1.6Ghz, inclusiv bucla de comparaţie, deci doar câteva  nanosecunde per comparaţie.



Problema apare cu calculul a ceea ce dorim sa afişăm. Dacă trimitem un string constant, practic se execută doar comparaţia. Dacă insă apelăm trace-ul cu un string calculat, el va fi evaluat chiar dacă nu va fi afişat. 

Schimbând stringul constant trace("a") cu trace("a" + i), unde i era long, numărul de operatii s-a redus de la 250 milioane/secundă la 5 milioane/secundă, iar cu un string putin mai lung la doar 1 milion/secundă. Inseamnă putin per operaţie dar se poate aduna dacă trace-ul este intr-o buclă în care se apelează de milioane de ori. In acest ultim caz, 100.000 trace-uri DEBUG pe secundă ar consuma 10% din procesor, chiar dacă nivelul de trace nu le-ar face să fie afişate.


Din acest punct de vedere, implementarea trace-urilor in C/C++ cu macrouri #define este mai eficientă, stringul de afişat este calculat doar daca nivelul de trace cere afişarea acelui trace. Teoretic si masina virtuală Java ar putea să detecteze că acel string nu merită calculat pentru că condiţia va fi falsă, dar in testele mele nu o face.

In Java, pentru a evita evaluarea stringului cănd nivelul de trace nu îl va afişa există soluţia de a nu concatena bucăţile de string înaintea apelului, ci în funcţia de trace. Dacă apelez de exemplu trace("a",i) şi fac concatenarea în interiorul if-ului, mă intorc la viteza mare de 250 milioane/secundă. In versiuni java mai recente se poate defini o functie de trace cu numar variabil de argumente trace(...), care va concatena orice numar de stringuri. Problema este că dacă unele dintre stringuri sunt calculate din diferite metode, metodele respective se vor apela totuşi, chiar dacă trace-ul nu va fi afişat.

Cel mai periculos este dacă pentru a construi textul apelăm metode complexe care iau mult timp. De asemenea, afişarea fişierului si liniei este mult mai lentă decăt afişarea unui trace fără aceste informaţii. Dacă programul rulează prea lent, incercaţi si fară afişarea fişierului şi liniei. Un sistem de trace centralizat are exact acest scop : puteţi schimba configuraţia pentru tot programul într-un singur loc.

Pentru locuri in care se execută peste 1000 operaţii pe secundă există posibilitatea de a pune apelul de trace într-un if, care va face ca textul trace-ului să fie evaluat doar când este activat modul DEBUG.


Capcane la folosirea trace-urilor

 Puteţi genera o excepţie neaşteptată chiar prin incercarea de a da un trace. Daca trace-ul cheamă o metodă a unui obiect null, va genera un NullPointerException.

 Situaţia este si mai gravă când trace-ul era urmare a unei excepţii, practic excepţia iniţială se pierde si se generează alta. Folosiţi in trace doar apeluri de care sunteţi siguri că nu pot genera erori/excepţii.

 Un trace prea des poate face programul instabil. Dacă de exemplu dăm un trace când detectâm ca programul răspunde prea încet, am putea agrava problema prin faptul că dam aceste avertismente. Câteaodată masurarea modifică obiectul măsurat... Evitaţi să apară cazuri in care warning-urile/erorile sunt repetate inutil, dacă problema persistă se pot re-afişa la anumite intervale.

 In C++, este posibil ca in funcţie de nivelul de trace configurat, anumite apeluri de funcţii sa se întâmple sau nu. Nu apelati in trace metode care modifică date !

Folosire Logger (log4j)

• Se recomandă folosirea unui sistem unitar de trace, astfel incât să putem gestiona global nivelul de trace si formatul de afişare. Dacă folosim o anumită bibliotecă, ar fi bine să folosim un sistem compatibil - de exemplu bibliotecile apache folosesc log4j.

• Există si un sistem de logare nativ in java (java.util.logging.Logger) dar pe mine nu m-a convins. Prefer log4j.

• In mod obişnuit fiecare clasă declară un membru
  

     static Logger log = Logger.getLogger( NumeClasa.class );

      In cadrul clasei putem apela apoi  (dupa ce am configurat un appender, găsiţi exemple pe Internet) :

   log.debug("mesaj debug")

   log.fatal("mesaj warning")

   log.fatal("mesaj eroare fatală", exceptie).

 

Membrul log se declară static pentru a nu se instanţia in fiecare obiect, ci doar unul per clasă. Argumentul este un string de fapt, mai exact se trimite numele clasei, se face implicit un .class.toString()

   Este preferabil să se trimită .class in loc de numele clasei intre ghilimele pentru că in primul caz schimbănd numele clasei (refactorizare) nu vom uita Logger-ul definit cu numele vechi.


 Numele clasei este trimis pentru a putea controla nivelul de logging pe fiecare clasă, de exemplu sa activăm nivelul DEBUG pe o anumită clasă dar să pastrăm doar nivelul WARNING la celelalte. Putem crea si loggere care să nu aparţină unei clase ci unui modul.




 Creaţi-vă propriul logger



 Dacă nu aveţi nevoie de setarea nivelului de trace diferit per clasă si nu vreţi sa folosiţi o bibliotecă externă precum log4j, puteţi folosi o clasă MyLogger care să aibă metode statice, care se pot apela prin MyLogger.warn("..."). 

Metodele trebuie să adauge data, nivelul de trace si eventual threadul si fisierul/linia, apoi sa apeleze System.err.println().

 Pentru a obtine fisierul si linia se poate examina stack-ul care se obtine prin "new Throwable().getStackTrace()".

 Mai târziu puteţi face această clasă să apeleze un alt logger, dar din pacate toate traceurile vor părea că vin din clasa MyLogger, nu din locul in care au fost chemate iniţial. Teoretic există o metodă de a afişa locaţia originală dar eu n-am reusit. Puteti totusi să obtineti asta dacă faceţi un wrapper peste Logger derivând o clasă din Logger si suprascriind anumite metode.




Bonus : o clasă simpla de trace-uri


O implementare de clasă care face trace-uri găsiti mai jos (cu titlu de exemplu). Nu este o capodoperă, dar vă poate da nişte idei:


package ro.mihvoi.trace;

import java.text.DateFormat;
import java.text.SimpleDateFormat;
import java.util.Calendar;


/*
 * MvTrace.java
 * 
 * This class provides a static methods to do traces with different trace levels
 * You can set at any time the trace level you want to actually print
 * You don't need to instantiate the class, just use the static methods
 * Normally the trace goes to stderr to not pollute the useful output
 * For Eclipse you can force it to stdout, to avoid red text
 * 
 *  You can put MVTRACE_LEVEL in evenironment to override the program's settings
 * 
 * Created on December 17, 2007, 9:31 PM
 *
 * To change this template, choose Tools | Template Manager
 * and open the template in the editor.
 */



/**
 *
 * @author mihvoi
 */


public class MvTrace {

    enum TraceLevel{
        DEBUG,
        INFO,
        NORMAL,
        WARNING,
        ERROR,
        FATAL
    }

    public static TraceLevel DEBUG=TraceLevel.DEBUG;
    public static TraceLevel VERBOSE=TraceLevel.INFO;
    public static TraceLevel NORMAL=TraceLevel.NORMAL;
    public static TraceLevel WARNING=TraceLevel.WARNING;
    public static TraceLevel RECOVERABLE=TraceLevel.ERROR;
    public static TraceLevel UNRECOVERABLE=TraceLevel.FATAL;


    private static String textForTraceLevel[] = {
        "UNRECOVERABLE",
        "RECOVERABLE  ",
        "WARNING      ",
        "====NORMAL===",
        "VERBOSE      ",
    "DEBUG        "};

    //private static MvTrace singletonMvTrace=null;
    private static boolean isInitializated=false;
    //private static int currentTraceLevel=MvTrace.NORMAL;
    private static TraceLevel currentTraceLevel=TraceLevel.DEBUG;
    private static TraceLevel _envTraceLevel = null; //This may override the currentTraceLevel set in the program

    //Last received trace, even not printed, to be printed with the unrecoverable errors
    private static String lastWarningTraceReceivedText;
    private static TraceLevel lastWarningTraceReceivedLevel;
    private static Calendar _calendar = Calendar.getInstance();
    private static DateFormat _dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");

    private static StringBuffer tmpStringBuffer = new StringBuffer();
    public static boolean _printFileLine = true;
    public static boolean _printDate = true;
    public static boolean _printThread = true;
    public static boolean _printColor = true;
    public static boolean _autoFlush = true;
    public static boolean _printOnStderr = true;
    public static boolean _printDebugForNormal = true;
    public static boolean _printFileLineInNormal = true;
    public static boolean _printOnStderrOnlyWarningAndErrors = false; //Set to true if you want to have DEBUG, VERBOSE on stdout instead on stderr
    public static int       _skipNbWrappersWhenPrintingStack = 0; //Use 1 if you call MvTrace from another trace wrapper, 2 for 2 wrappers

    static {
        String envLevel = System.getenv("MVTRACE_LEVEL");

        if(envLevel != null){
            TraceLevel level = getTraceLevelByName(envLevel);
            //MvTrace.printRecoverable("Level : " + level);
            if(level == null){
                MvTrace.printRecoverable("Unknows trace level in environment variable MVTRACE_LEVEL=\"" + envLevel + "\" , valid options are : " + getTraceLevelList());
            }else{
                MvTrace.printWarning("Using level set in environment MVTRACE_LEVEL=" + envLevel);
                _envTraceLevel = level;
            }
        }
    }

    public static String getTraceLevelList(){
        String values = "[";
        for(TraceLevel level : TraceLevel.values()){
            values += " " + level + ",";
        }
        values += ']';

        return values;       
    }

    public static TraceLevel getTraceLevelByName(String traceLevelString){
        //MvTrace.printRecoverable("Searching for level = " + traceLevelString);
        TraceLevel level = null;

        try{
            level  = TraceLevel.valueOf(traceLevelString);
        }catch(IllegalArgumentException e){
            //MvTrace.printRecoverable("Unknow trace level : " + traceLevelString + " valid values : " + getTraceLevelList() );
            return null;
        }

        //MvTrace.printWarning("Received " + level);
        return level;
    }

    //Slower
    public static boolean setTraceLevelSlow(String newTraceLevel){

        TraceLevel level = getTraceLevelByName(newTraceLevel);
        if(level != null){
            setTraceLevel(level);
            return true;
        }

        StringBuffer sb = new StringBuffer();
        for (int i=0; i < textForTraceLevel.length; i++) {
            if (i != 0) sb.append(", ");
            sb.append(textForTraceLevel[i].toString());
        }
        MvTrace.printRecoverable("Unknown trace level string : \"" + newTraceLevel + "\". Valid trace levels are: " + sb);
        MvTrace.printRecoverable("Trace level unchanged (" + currentTraceLevel + ")");
        return false;       
    }

    public static TraceLevel setTraceLevel(int newTraceLevel){
        TraceLevel level = TraceLevel.values()[newTraceLevel];
        return setTraceLevel(level);
    }


    public static TraceLevel setTraceLevel(TraceLevel newTraceLevel){
        TraceLevel oldTraceLevel;
        oldTraceLevel=currentTraceLevel;
        currentTraceLevel=newTraceLevel;
        return oldTraceLevel;
    }

    static void initializate(TraceLevel aTraceLevel){

        if(isInitializated){
            printRecoverable("Trace already initializated");
            System.out.println("W: Trace already initializated");
        }

        isInitializated=true;
        currentTraceLevel=aTraceLevel;
        //_dateFormat = new SimpleDateFormat("zzz"+PS+"yyyy-MM-dd"+PS+"dd-HH-mm"+PS+"ss-SSS");


        System.out.println("Trace system initialized with level: " + currentTraceLevel);
    }

    public static void debug(String aText){
        printTraceWithLevel(DEBUG, aText, null);
    }

    public static void printDebug(String aText){
        printTraceWithLevel(DEBUG, aText, null);
        //return this;
    }

    public static void printNormal(String aText){
        printTraceWithLevel(NORMAL, aText, null);
        //return this;
    }

    public static void print(String aText){
        printTraceWithLevel(NORMAL, aText, null);
        //return this;
    }

    public static void printVerbose(String aText){
        printTraceWithLevel(VERBOSE, aText, null);
        //return this;
    }

    public static void info(String aText){
        printTraceWithLevel(VERBOSE, aText, null);
        //return this;
    }

    public static void printWarning(String aText){
        printTraceWithLevel(WARNING, aText, null);
        //return this;
    }

    public static void warn(String aText){
        printTraceWithLevel(WARNING, aText, null);
        //return this;
    }
   
       public static void warn(String aText, Exception t){
            printTraceWithLevel(WARNING, aText, t);
            //return this;
        }

    public static void printWarning(String aText, Exception t){
        printTraceWithLevel(WARNING, aText, t);
        //return this;
    }

    public static void printRecoverable(String aText){
        printTraceWithLevel(RECOVERABLE, aText, null);
        //return this;
    }

    public static void error(String aText){
        printTraceWithLevel(RECOVERABLE, aText, null);
        //return this;
    }

    public static void printRecoverable(String aText, Exception t){
        printTraceWithLevel(RECOVERABLE, aText, t);
        //return this;
    }

    public static void error(String aText, Exception t){
        printTraceWithLevel(RECOVERABLE, aText, t);
        //return this;
    }

    public static void printUnrecoverable(String aText){
        printTraceWithLevel(UNRECOVERABLE, aText, null);
        //return this;
    }

    public static void fatal(String aText){
        printTraceWithLevel(UNRECOVERABLE, aText, null);
        //return this;
    }

    public static void printUnrecoverable(String aText, Exception t){
        printTraceWithLevel(UNRECOVERABLE, aText, t);
        //return this;
    }

    public static void fatal(String aText, Exception t){
        printTraceWithLevel(UNRECOVERABLE, aText, t);
        //return this;
    }


    public static void checkAssertExit(boolean aConditionThatShouldBeTrue, String aText){

        if(! aConditionThatShouldBeTrue){
            printTraceWithLevel(lastWarningTraceReceivedLevel,lastWarningTraceReceivedText, null);
            printTraceWithLevel(UNRECOVERABLE, aText, null);
            System.exit(-1);
        }
        // return this;
    }

    static protected void printTraceWithLevel(TraceLevel aTraceLevel, String aTraceText, Exception t){

        synchronized (tmpStringBuffer) {

            //Set the last warning even if it is not printed
            if( aTraceLevel.compareTo( TraceLevel.WARNING) > 0){
                lastWarningTraceReceivedText=aTraceText;
                lastWarningTraceReceivedLevel=aTraceLevel;
            }

            //Will continue printing the trace with break, will not print trace if call return
            if(aTraceLevel != TraceLevel.NORMAL){ //Always print NORMAL

                if(_envTraceLevel == null){ //No environment overwrite of trace level   
                    if( aTraceLevel.compareTo(currentTraceLevel) < 0 ){
                        return;
                    }

                }else{ //There is an evironment trace level set
                    if( aTraceLevel.compareTo(_envTraceLevel) < 0 ){
                        return;
                    }
                }
            }//if(aTraceLevel != TraceLevel.NORMAL){


            //System.out.println("DEBUG [" + textForTraceLevel[aTraceLevel] + "] : " + aTraceText + "Current "+currentTraceLevel + " Level" + aTraceLevel);

            tmpStringBuffer.setLength(0);

            if(_printColor){
                if(aTraceLevel.compareTo(WARNING) >= 0){
                    tmpStringBuffer.append("\u001B[31m");
                    //tmpStringBuffer.append("!!!!!! ");
                    //"\u001B[35m"
                }

            }

            if(_printDate){
                _calendar.setTimeInMillis(java.lang.System.currentTimeMillis());
                String date = _dateFormat.format(_calendar.getTime());
                tmpStringBuffer.append(date);
            }

            if(_printThread && ( (aTraceLevel!=NORMAL) || _printDebugForNormal ) ){
                String threadName = Thread.currentThread().getName();
                long threadId = Thread.currentThread().getId();
                tmpStringBuffer.append(" [thr");

                //String threadName = Thread.currentThread().getName();
                //tmpStringBuffer.append(threadName);

                String thread3Digits = String.format("%03d", threadId);
                tmpStringBuffer.append(thread3Digits);
                tmpStringBuffer.append("_");


                tmpStringBuffer.append(String.format("%-20s", threadName) );       
                tmpStringBuffer.append("]");
            }

            if( (_printDebugForNormal==true) || (aTraceLevel!=NORMAL)){
                tmpStringBuffer.append(" [");
                tmpStringBuffer.append( String.format("%-7s", aTraceLevel) );
                tmpStringBuffer.append("]");
            }

            tmpStringBuffer.append(" ");
            tmpStringBuffer.append(aTraceText);

            if(_printFileLine && ( (_printDebugForNormal==true) || (aTraceLevel!=NORMAL || _printFileLineInNormal)) ){
                Throwable aThrowable = new Throwable();
                StackTraceElement className[]= aThrowable.getStackTrace();
                //tmpStringBuffer.append(" <= ");
                StackTraceElement stackElement = className[2 + _skipNbWrappersWhenPrintingStack ];
                //Not working in old Eclipse
                tmpStringBuffer.append(" (" + stackElement.getFileName() + ":" + stackElement.getLineNumber() + ")");
                //tmpStringBuffer.append(" " + stackElement.toString() );

            }

            //[0].getClassName();
            //First 2 are:
            //Nume clasa: atomdatabase.MvTrace.printTraceWithLevel(MvTrace.java:84)
            //Nume clasa: atomdatabase.MvTrace.printDebug(MvTrace.java:46)
            //for (int i=0; i< className.length ; i++){
            //    function_name=function_name.concat(className[i].toString());
            //    //System.out.println("Nume clasa: " + className[i]);
            //}

            //System.out.println(  date + " [thr" + threadId + "]" + " [" + textForTraceLevel[aTraceLevel] + "] : " + aTraceText );


            if(t != null){

                //tmpStringBuffer.append("\nException message : ");
                //tmpStringBuffer.append( t.getMessage() );
                tmpStringBuffer.append("\n\n");

                //tmpStringBuffer.append("\nSTACKKKKKKKKKKKKKKKKK");
                StringBuilder fullStack = new StringBuilder();
                StringBuilder currentCauseStack = new StringBuilder();

                fullStack.setLength(0);
                Throwable cause = t;

                do{
                    currentCauseStack.setLength(0); //Set empty

                    currentCauseStack.append("\nException msg : " + cause.getMessage() + " " + cause.getClass() + "\nStack:");

                    StackTraceElement a[] = cause.getStackTrace();

                    for(int i=0; i < a.length ; i++){
                        currentCauseStack.append("\n");
                        currentCauseStack.append(a[i].toString());
                    }

                    cause=cause.getCause();

                    fullStack.append(currentCauseStack);
                    //fullStack.insert(0,currentCauseStack);

                    if(cause != null){
                        fullStack.append("\n\n...CAUSED BY:");
                    }

                }while(cause != null);

                tmpStringBuffer.append(fullStack);
                tmpStringBuffer.append("\n");
            }//if(t != null){ - on exception

            if(_printColor){
                if(aTraceLevel.compareTo( WARNING ) >= 0){
                    tmpStringBuffer.append("\u001B[0m");
                    //Sane
                }

            }

            //tmpStringBuffer.append("END\n");

            //if(aTraceLevel > WARNING){
            if( _printOnStderr &&
                    (
                            (!_printOnStderrOnlyWarningAndErrors && aTraceLevel != NORMAL) 
                            ||
                            (_printOnStderrOnlyWarningAndErrors && (aTraceLevel.compareTo(NORMAL) > 0) )
                    )
            ){

                System.err.println(tmpStringBuffer);

                if(_autoFlush){
                    System.err.flush();
                }           

            }else{

                System.out.println(tmpStringBuffer);

                if(_autoFlush){
                    System.out.flush();
                }

            }


            //return this;

        }
    };

    //Use "MvTrace.init(traceLevel)" instead of new !
    //Private constructor

    private MvTrace() {
        //currentTraceLevel=traceLevel;
        System.out.println("Trace system initializated with level: " + currentTraceLevel);
    }



    public static void main(String[] args) {
        MvTrace._printColor = false;
        MvTrace._printOnStderrOnlyWarningAndErrors = true;
        System.out.println("MvTrace 5 test");
        MvTrace.debug("Trace debug");
        MvTrace.warn("Verbose");
        MvTrace.print("A normal operation message");
        MvTrace.warn("Warning");
        MvTrace.error("Recoverable");
        MvTrace.setTraceLevel(MvTrace.VERBOSE);
        //MvTrace.setTraceLevel(newTraceLevel)
        MvTrace.debug("Trace debug will not be printed");
        MvTrace.info("Verbose will be printed");
        MvTrace.fatal("Unrecoverable2", new RuntimeException("Test exception"));
        MvTrace.fatal("Unrecoverable3");

        //This will exit
        MvTrace.checkAssertExit( 1==2 , "1==2");


        //MvTrace.printDebug("Debug trace");
    }

}


Adăugare Iunie 2011


 Am scris acest post când nu cunoşteam foarte bine bibliotecile de logging Java, precum log4j, slf4j. Nici acum nu cunosc tot, dar am mai învăţat câte ceva.


 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.info("Connecting to database..."); 


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:
 import org.apache.log4j.Logger;

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


 Este mai laborios de folosit decât varianta cu metode statice, dar 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 şi din din program, de exemplu în funcţia main() cu:
 Logger.getLogger("").setLevel(Level.DEBUG); //Setează nivelul de log default
- Dacă foloseşti anumite bilioteci (apache mai ales), ele vor loga oricum folosind log4j

 continuare aici

"The more I say, the more I know" . Republicarea articolelor este permisă cu citarea autorului