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
Parallel Studio XE 2015
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-2015. Alcuni diritti riservati. Testata giornalistica iscritta col n. 569 presso il Tribunale di Milano in data 14/10/2002. Pagina generata in 0.425 secondi.