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:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern> </encoder>
</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:
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:
...
public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = //Lengthy printing operation
log.debug("Leaving printDocument(): {}", id); return id;
}
...
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:
...
Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
log.debug("Processing ids: {}", requestIds);else
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:
...
log.error("IO exception", e);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:
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:
...
log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)
...