Programmazione.it v6.4
Ciao, per farti riconoscere devi fare il login. Non ti sei ancora iscritto? Che aspetti, registrati adesso!
Info Pubblicità Collabora Autori Sottoscrizioni Preferiti Bozze Scheda personale Privacy Archivio Libri Corsi per principianti Forum
10 consigli su come implementare il logging nelle proprie applicazioni (3/3)
Scritto da Francesco Carotenuto il 29-07-2011 ore 09:35
C'è da tener conto che molti programmatori adoperano, per la scrittura di log, un messaggio che può essere composto da una serie di caratteri, un hash, una stringa alfanumerica pseudo-casuale e un messaggio descrittivo sull'oggetto con id XYZ, e tale messaggio è praticamente sempre lo stesso, ottenendo così file log inutilmente ingombranti e poco leggibili.

Per cui bisogna evitare tale pratica, altrimenti detta magic log, e concentrarsi nell'ottenimento di file log puliti leggibili e descrittivi. Atteso che un log ben scritto può essere una grande fonte di informazione per la documentazione del codice dell'applicazione, concludiamo questa trilogia con l'incoraggiamento a non usare nel logging alcuna informazione personale.

Un utile consiglio è quello di realizzare un logging pattern, che in maniera del tutto trasparente aggiunga un contesto alle istruzione di logging create. Esso devo includere: l'ora corrente (senza data e con precisione al millisecondo), livello di logging, nome del thread che si sta loggando, un identificativo e ovviamente la descrizione dell'evento. Pertanto utilizzando un framework come logback possiamo realizzare il logging pattern nel seguente modo:
  1. <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
  2.     <encoder>
  3.         <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
  4.     </encoder>
  5. </appender>
Al contrario, non si dovrebbero mai includere nel logging pattern i nomi di file, classi e numero di riga del codice; molti programmatori credono che il numero di linea appartenga al logging pattern e di conseguenza usano introdurre istruzioni di questo tipo:
  1. ...
  2. log.info("");
  3. ...
in modo da poter ottenere il numero di linea del codice, che dovrebbe consentire l'effetto desiderato, non curandosi del fatto che tale approccio porta a fare il logging di altre informazioni, come il nome della classe e del metodo, che possono comportare una perdita nelle performance dell'applicazione.

Un utile consiglio, soprattutto in vista della messa in produzione dell'applicazione, è quello di effettuare il log di tutti i parametri d'ingresso e di uscita, oltre che dei dati restituiti dai metodi, così come effettuato nel seguente codice:
  1. ...
  2. public String printDocument(Document doc, Mode mode) {
  3.     log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
  4.     String id = //Lengthy printing operation
  5.     log.debug("Leaving printDocument(): {}", id);
  6.     return id;
  7.  
  8. }
  9. ...
A questo scopo si dovrebbe considerare l'uso dei livelli DEBUG e TRACE; se ci si trova davanti a metodi che vengono chiamati molte volte, allora si può pensare di usare i livelli di classe inferiore o addirittura rimuovere il logging, in modo da migliorare le performance. Tuttavia, c'è da dire che è sempre preferibile avere un esubero di informazioni piuttosto che averne troppo poche. Nel caso di integrazione di più sistemi tra loro, è bene effettuare il logging di tutti i dati in entrata e in uscita che il proprio sistema scambia con sistemi esterni.

Siccome le informazioni scambiate possono essere tantissime e fare il logging può essere molto oneroso in termini di performance; si può pensare dunque di effettuare il logging in produzione per un breve periodo di tempo, ad esempio fino al rilevamento di un malfunzionamento, utilizzando opportunamente i livelli di log come in questo esempio:
  1. ...
  2. Collection<Integer> requestIds = //...
  3.  
  4. if(log.isDebugEnabled())
  5.     log.debug("Processing ids: {}", requestIds);
  6. else
  7.     log.info("Processing ids size: {}", requestIds.size());
Se il logger è su debug allora si stamperanno tutti gli id delle richieste ricevute memorizzate in una collezione, altrimenti si stampa solo la dimensione di tale collezione come INFO. Il tutto a patto che la collezione non sia vuota.

A questo punto possiamo parlare un po' del logging delle eccezioni, già loggate più che adeguatamente dai vari framework e container basati su Java, e del paradigma client/server (a patto che il client abbia tutte le classi necessarie e la possibilità di de-serializzare l'eccezione lanciata).

Ad ogni modo molti programmatori tendono a usare il logging come un sistema per trattare le eccezioni senza in effetti gestirle, oppure arrivano a fare il log di un'eccezione e poi il wrapping all'interno di un'altra eccezione, che viene a sua volta rilanciata, così come illustrato in questo codice, ottenendo per ben due volte il logging dello stesso stack trace:
  1. ...
  2. log.error("IO exception", e);
  3. throw new MyCustomException(e);
Se proprio si vuole fare il log di un'eccezione (per lo più per pigrizia di leggere la documentazione) è meglio procedere nel seguente modo, così da prevenire per lo meno le ridondanze:
  1. ...
  2. try {
  3.     Integer x = null;
  4.     ++x;
  5. } catch (Exception e) {
  6.     log.error("", e);       
  7. }
  8. ...
Concludiamo ricordando che i fruitori dei log possono essere uomini o computer, che utilizzano il log ricevuto all'interno di script di Shell; pertanto si consiglia di produrre del log comprensibile e facilmente gestibile da entrambi i fruitori, evitando la formattazione dei numeri, utilizzando pattern, che possono essere facilmente riconosciuti da espressioni regolari e se ciò non è possibile, scrivendo la data in due formati, così come illustrato in questo snippet, utilizzando tool come il DurationFormatUtils:
  1. ...
  2. log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
  3. // Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
  4. final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
  5. log.info("Importing took: {}ms ({})", durationMillis, duration);
  6. //Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)
  7. ...
Precedente: CodeWarrior, un IDE per lo sviluppo di sistemi embedded (4/10)
Successiva: Un buon programmatore è un cattivo progettista?
Intervento di Simone F a.k.a. laserpez del 29-07-2011 ore 18:19, Ferrara (FE)
Plebeo
Plebeo
(10 interventi)
Iscritto il 09-04-2009
Qual è il rationale dietro questo consiglio:

"Esso [il log] devo includere: l'ora corrente (senza data e con precisione al millisecondo) ..."

Perché non dovrebbe apparire la data?
Intervento di Francesco Carotenuto a.k.a. nucarote del 31-07-2011 ore 22:40, Nocera inferiore (SA)
Plebeo
Plebeo
(44 interventi)
Iscritto il 14-01-2009
laserpez ha scritto:
Qual è il rationale dietro questo consiglio:

"Esso [il log] devo includere: l'ora corrente (senza data e con precisione al millisecondo) ..."

Perché non dovrebbe apparire la data?

Unica idea che mi sovviene è che invece di stampare per ogni log la data (il che rende il file log più ridondante e si può perdere qualcosa in termini di perfomance), si potrebbe pensare di organizzare i logs su più file di log, generati ogni qual volta si esegua il codice, e che il nome del file log sia un timestamp (che sarebbe poi il tempo d'inizio esecuzione), ed esso contenga tutti gli eventi registrati che riportano orari successivi al timestamp.
http://logback.qos.ch/manual/appenders.html#uniquelyNamed
Copyright Programmazione.it™ 1999-2014. Alcuni diritti riservati. Testata giornalistica iscritta col n. 569 presso il Tribunale di Milano in data 14/10/2002. Pagina generata in 0.41 secondi.