Nerd Notes

/dev/brain: no space left on device

Posts Tagged ‘logging

Ulteriori elucubrazioni sull’impiego di slf4j e logback

with one comment

In seguito al mio precedente post scrivi messaggi di log decenti, altrimenti Gesù piange, alcuni colleghi hanno iniziato ad usare slf4j e logback come framework di logging. Quando si inizia ad usare questa roba ci si scontra subito con un problema classico che è quello della convivenza fra framework di logging. Senza scendere troppo in dettagli immediatamente, dirò che lo scopo di questo post è quello di spiegare come fare in modo che, una volta consolidata la scelta di slf4j come api e logback come implementazione, indipendentemente dai framework di logging in uso nella nostra applicazione, l’output dei log sia gestito in maniera centralizzata ed unica tramite logback (quindi tramite il file logback.xml).

In altre parole, nella nostra applicazione ci troveremo a dover gestire una situazione in cui ci saranno classi nostre che usano l’api di slf4j ed altre classi non gestite da noi che usano log4j piuttosto che jakarta-commons-logging (jcl per gli amici) o java.util.logging (jul per gli amici).

Prima di tutto una premessa doverosa: le istruzioni che seguono funzioneranno solo in un ambiente in cui il classloader dà la precedenza nel caricamento delle classi a quelle che si trovano all’interno dei nostri artefatti e non a quelle fornite con l’application server. Per capirci, se il nostro applicativo è un war da installare su tomcat, funzionerà tutto correttamente. Se invece il nostro applicativo è una ear da installare su jboss application server, le indicazioni non funzioneranno perché il classloader di jboss darà la precedenza alle classi di log4j e jakarta-commons-logging fornite col server.

In soldoni, bisogna fare in modo che nella directory WEB-INF/lib del nostro war non ci siano i jar delle implementazioni di log4j e jakarta-commons-logging ma piuttosto dei jar di slf4j che contengono delle classi wrapper che si sostituiscono a quelle di log4j e jakarta-commons-logging facendo in modo che l’implementazione delle interfacce di log venga intercettata e dirottata verso slf4j e quindi logback.

Questo in maven si traduce in un pom di questo tipo:

<dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>commons-logging</groupId>
                <artifactId>commons-logging</artifactId>
                <version>1.1</version>
                <scope>provided</scope>
            </dependency>
            <dependency>
                <groupId>commons-logging</groupId>
                <artifactId>commons-logging-api</artifactId>
                <version>1.1</version>
                <scope>provided</scope>
            </dependency>
            <dependency>
                <groupId>log4j</groupId>
                <artifactId>log4j</artifactId>
                <version>1.2.15</version>
                <scope>provided</scope>
            </dependency>

            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>slf4j-api</artifactId>
                <version>1.5.10</version>
            </dependency>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>jcl-over-slf4j</artifactId>
                <version>1.5.10</version>
            </dependency>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>log4j-over-slf4j</artifactId>
                <version>1.5.10</version>
            </dependency>
            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-core</artifactId>
                <version>0.9.18</version>
            </dependency>
            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-classic</artifactId>
                <version>0.9.18</version>
            </dependency>
        </dependencies>
</dependencyManagement>

Bene. Ora, a cosa serve un blocco dependencyManagement? A dichiarare dei default, tant’è vero che tipicamente la sezione dependencyManagement viene specificata nel pom padre del progetto, quello principale per capirci. Andiamo un po’ a vedere i vari blocchi a cosa servono.

Le prime tre dichiarazioni servono per dichiarare in modo globale che gli artefatti (e quindi i relativi jar) di commons-logging, commons-logging-api e log4j sono forniti dal contesto di deployment (in altre parole sono forniti con il jdk oppure si trovano in una directory lib o endorsed dell’application server). In pratica dichiarare come provided queste dipendenze è  un trucco per fare in modo che i jar di log4j e di commons-logging non vadano a finire dentro WEB-INF/lib, altrimenti bisognerebbe analizzare l’albero delle dipendenze del progetto e dichiarare tante di quelle esclusioni sulle dipendenze transitive da morirci gonfi.

Le altre dichiarazioni servono solo a stabilire dei default sulle versioni dei jar che ci interessano. Le dichiarazioni vere e proprie delle dipendenze va fatta sul pom che produce il war, a questo punto senza specificare versioni perché verranno impiegati i default stabiliti in precedenza dentro al blocco dependencyManagement:

        <dependencies>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>slf4j-api</artifactId>
            </dependency>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>jcl-over-slf4j</artifactId>
            </dependency>
            <dependency>
                <groupId>org.slf4j</groupId>
                <artifactId>log4j-over-slf4j</artifactId>
            </dependency>
            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-core</artifactId>
            </dependency>
            <dependency>
                <groupId>ch.qos.logback</groupId>
                <artifactId>logback-classic</artifactId>
            </dependency>
        </dependencies>

La verifica ultima va fatta andando a controllare il contenuto del war. Se abbiamo fatto bene il nostro lavoro, nella directory WEB-INF/lib del war non dobbiamo trovare alcun jar di commons-logging né di log4j. Dovremmo invece trovare questi jar:

  • jcl-over-slf4j-1.5.10.jar
  • log4j-over-slf4j-1.5.10.jar
  • logback-classic-0.9.18.jar
  • logback-core-0.9.18.jar
  • slf4j-api-1.5.10.jar

Per ulteriori dettagli vi rimando alla documentazione dei relativi framework, in particolare alla pagina bridging legacy APIs nella documentazione di slf4j.

Advertisements

Written by Mirko Caserta

October 13, 2010 at 3:10 pm

Scrivi messaggi di log decenti, altrimenti Gesù piange

with 3 comments

Vorrei proporre alcune considerazioni sulla apparentemente oscura arte dello scrivere messaggi di log. Dico apparentemente oscura perché si tratta di un argomento apparentemente banale ma che in realtà si rivela complesso. Trattandosi di osservazioni generali, queste andrebbero prese con una dose di buon senso e sotto stretta osservazione del proctologo di fiducia; ciò non toglie che con ogni probabilità troverai le seguenti note ragionevolmente utili poiché basate sull’esperienza personale (a.k.a. sangue versato sul campo).

Niente guerre di religione, altrimenti Feuerbach piange

Nel mondo java, log4j è considerato lo standard de facto quando si parla di framework di logging. Tuttavia, il mio consiglio è di usare un framework più moderno, come slf4j o logback. Logback è basato sull’api di slf4j ed è sufficiente dare un’occhiata agli esempi nella documentazione per essere produttivi nel giro di un quarto d’ora. Vorrei evitare di spiegare i vantaggi di questi framework rispetto (ad esempio) a log4j o java.util.logging perché credo l’argomento sia non solo abbondantemente trattato in letteratura ma anche facilmente foriero di guerre di religione. Le guerre di religione sono per definizione irrazionali nonché mortalmente tediose. Sei abbastanza intelligente da documentarti e decidere da solo.

Al di là di un eventuale framework e del linguaggio di programmazione usato, i messaggi di log sono essenziali sia in fase di test/debug che in fase di monitoring in produzione. Il log è spesso sottovalutato e trattato come una seccatura che va espletata più per dovere che per una reale necessità. Tuttavia, ti posso assicurare che non c’è nulla di peggio che essere chiamati a risolvere un problema urgente in produzione e trovarsi davanti ad un log incasinato. In particolare, nel momento in cui qualche migliaio di utenti è in procinto di spendere un mucchio di soldi sul sito del tuo cliente e l’applicazione è scritta da te e per qualche oscuro motivo la possibilità di tale ingente esborso dovesse essere negata agli utenti del suddetto sito, vorrai essere sicuro di avere la possibilità di capire velocemente cosa sta succedendo dietro le quinte. In casi simili, dire che a scrivere male nel log Gesù piange è al massimo un eufemismo neanche troppo colorito.

Garbage in, garbage out

Uno dei concetti elementari del software è quello di input/output. Conoscendo l’input e lo stato di tutte le variabili coinvolte nel processo di elaborazione, sai che puoi aspettarti un certo output. Se l’output non è coerente con le aspettative, vorrà dire che analizzando il contesto, l’input, il codice e lo stato delle variabili locali e globali coinvolte, dovresti riuscire a capire cosa non quadra. Non è necessario tracciare nel log ogni cambiamento di stato di ogni variabile, specie se la funzione o il metodo sono sufficientemente complessi.

Esempio di log inutile:

public BuyResponse buyItem(BuyRequest request) {
log.debug(" ----- buyItem ------ start -----");
// ...
log.debug(" ----- buyItem ------ stop -----");
return response;
}

Esempio di log più utile:

public BuyResponse buyItem(BuyRequest request) {
log.debug("buyItem(): request={}", request);
// ...
log.debug("buyItem(): request={}, response={}", new Object[]{request, response});
return response;
}

In questo modo posso controllare l’input e l’output del metodo. Ripetendo l’input anche all’uscita del metodo, sarà più facile correlare i messaggi in fase di analisi del log. Tuttavia non sempre è utile questo tipo di verbosità. Come al solito, il buon senso dovrebbe guidarti nella scelta. Ad ogni modo, input, output e cambiamenti di stato di variabili importanti andrebbero tracciati almeno a livello di debug.

Loggare a un certo livello

Tutti i framework di logging hanno un meccanismo di livelli per cui è possibile filtrare l’output in modo da ottenere solo i messaggi che davvero ci interessano. Spesso capita di fare copia e incolla di statement di log per cui un messaggio che dovrebbe essere a livello di errore invece finisce a livello di debug. Occhio al copia e incolla!

Formattazione coerente e senza fronzoli

Cerca di mantenere uno stile coerente e senza troppi fronzoli nei messaggi di log. Disattiva il “blocco maiuscole”, abbi pietà. Questo ti aiuterà nella fase di analisi ed eviterà che le tue applicazioni abbiano l’aspetto di una roba scritta da uno sbarbatello in visual basic.

Metti i messaggi in riga

Per quanto possibile, evita di introdurre caratteri di a capo nei messaggi di log. Quando userai grep per andare alla ricerca dei messaggi che ti interessano, è importante che ad una riga di output corrisponda un messaggio coerente. All’inizio, andare a capo sembra dare un aspetto migliore all’output ma col tempo ti renderai conto che avresti fatto meglio a non farlo.

Occhio al copia e incolla

Come già accennato, può capitare di fare copia e incolla di statement di log. Ogni volta che faccio copia e incolla, si accende una speciale lampadina nella mia testa che serve a ricordarmi: “controlla ciò che hai copiato almeno due volte perché sicuramente hai dimenticato di modificare qualcosa che avresti dovuto modificare”. Questo vale più in generale e non solo per i messaggi di log. Se avessi avuto un euro per ogni frammento di codice sbagliato (non escluso il mio) per via di un copia e incolla frettoloso, in questo momento sarei sulla spiaggia di un’isola tropicale a sorseggiare un cocktail attorniato da compiacenti signorine.

Eccezioni

Il log di un errore dovrebbe portarsi dietro l’istanza di eccezione catturata e, se possibile ed utile, un minimo di contesto. Spesso mi capita di vedere codice del tipo:

catch (ConnectionException e) {
log.error("Error: " + e);
}

Sarebbe decisamente meglio una cosa del genere:

catch (ConnectionException e) {
log.error("connection error: user=" + user, e);
}

In questo modo non perdo lo stack trace dell’eccezione scatenata e posso ricondurla ad una specifica istanza di utente.

Conosci il tuo framework

Altrettanto importante è conoscere i meccanismi di deployment e configurazione del framework che stai usando. Potrebbe tornarti utile ad esempio impostare un filtro specifico su un certo logger. Impara inoltre a conoscere i meccanismi di formattazione dei messaggi. Configurando opportunamente un formatter, i framework moderni permettono di tracciare ad esempio timestamp al millisecondo, nomi di classi e metodi e nome del thread. Il nome del thread è essenziale in un’applicazione concorrente per seguire il flusso di esecuzione del software. Non c’è nulla di più frustrante di dover analizzare un log in cui non è presente il nome del thread.

Written by Mirko Caserta

October 2, 2009 at 8:45 pm