Formattazione e livelli di log: best practices

1. Struttura di un messaggio di log

Immaginiamo che i log non siano solo un “flusso di coscienza” del vostro programma, ma un prezioso registro in cui tra un mese o un anno voi o un collega potrete trovare la risposta alla domanda: “Che cosa diamine è successo qui?”. Perché ciò sia possibile, ogni messaggio di log deve essere strutturato. Di solito (ed è lo standard nella maggior parte delle librerie) ogni messaggio contiene:

• Timestamp dell’evento — quando è successo.
• Livello — quanto è importante (INFO, ERROR ecc.).
• Nome del logger — di solito è il nome della classe o del componente.
• Testo del messaggio — che cosa è successo esattamente.
• Stack trace (se c’è un errore) — per capire dove e perché.

Ecco un esempio di riga di log ben formattata (Log4j/SLF4J):

2024-06-16 18:42:07,123 INFO  com.example.MainApp - L'utente ha effettuato l'accesso: username=vasya

E se si è verificato un errore:

2024-06-16 18:42:10,456 ERROR com.example.LoginService - Errore di autorizzazione dell'utente: vasya
java.lang.IllegalArgumentException: Password non valida
    at com.example.LoginService.checkPassword(LoginService.java:42)
    ...

Perché è importante?
Quando un’applicazione gira a lungo, i log possono occupare gigabyte. Se i messaggi non sono strutturati, trovare il problema diventa un esercizio tipo “indovina la melodia dal rumore della ventola”.

2. Formattazione dei messaggi

Perché non è consigliabile fare così:

logger.info("Utente " + username + " ha effettuato l'accesso");

Sembra tutto semplice, ma c’è una trappola: anche se il livello di logging è impostato su ERROR, la stringa all’interno delle parentesi verrà comunque costruita (la concatenazione verrà eseguita), e questo è uno spreco di risorse. Nei sistemi di grandi dimensioni, dove i log producono migliaia di righe al secondo, ciò può tradursi in ritardi reali.

Modo corretto: placeholder e parametri

Le librerie moderne (ad esempio SLF4J e Log4j 2) supportano template con parametri:

logger.info("L'utente {} ha effettuato l'accesso", username);

Qui la stringa verrà costruita solo se il livello di logging consente di emettere questo messaggio. Se ad esempio è impostato WARN, non avverrà nemmeno il calcolo della stringa — risparmio di risorse e di nervi.

Bonus: se si passano più parametri, verranno sostituiti in ordine:

logger.info("L'utente {} ha eseguito l'azione {} sull'oggetto {}", username, action, objectId);

Registrazione delle eccezioni (stack trace)

Se intercettate un’eccezione, non aggiungete manualmente lo stack trace al messaggio:

// NON FARLO:
logger.error("Errore: " + ex.getMessage() + "\n" + Arrays.toString(ex.getStackTrace()));

Corretto:

logger.error("Errore durante l'elaborazione della richiesta", ex);

SLF4J e Log4j aggiungeranno automaticamente lo stack trace al log.

Esempio: confronto degli approcci

// Male (la concatenazione viene eseguita sempre)
logger.debug("Oggetto: " + expensiveToString(obj));

// Bene (formazione lazy)
logger.debug("Oggetto: {}", obj);

3. Scelta dei livelli di log

Se nei log avete tutto al livello ERROR, non sono più log ma una “spia rossa”. Se tutto è a DEBUG, annegherete nei dettagli. Vediamo quando usare ciascun livello.

ERROR

WARN

INFO

DEBUG

TRACE

Esempi di messaggi tipici

• ERROR — impossibile scrivere il file, eccezione non gestita catturata, servizio non disponibile.
• WARN — API deprecata, comportamento sospetto dell’utente, superato il limite dei tentativi.
• INFO — utente entrato/uscito, elaborazione ordine completata, avvio dell’applicazione.
• DEBUG — parametri della richiesta, valori delle variabili, risultati intermedi dei calcoli.
• TRACE — ingresso/uscita dai metodi, cicli interni, dettagli del funzionamento degli algoritmi.

Consiglio:
In produzione di solito si abilitano solo INFO e superiori, talvolta WARN e ERROR. DEBUG e TRACE — solo nella ricerca di bug complessi.

4. Best practices (buone pratiche di logging)

Non registrate dati sensibili

Password, token, numeri di carte di credito — non appartengono ai log. Anche se sembra che “il file di log sia solo per me”, ricordate il GDPR e il collega che per sbaglio invierà il log nella chat generale.

// Male:
logger.info("L'utente {} ha effettuato l'accesso con la password {}", username, password);

// Bene:
logger.info("L'utente {} ha effettuato l'accesso", username);

Non abusate del livello ERROR

Se scrivete tutto tramite logger.error, quando si verificherà davvero una catastrofe nessuno la noterà — tutti si saranno abituati alle “spie rosse”. Usate ERROR solo per situazioni in cui l’applicazione non può davvero continuare a funzionare o è violata la logica di business.

Registrate le eccezioni con lo stack completo

Non scrivete solo ex.getMessage(), altrimenti non saprete mai dove è avvenuto l’errore. Passate l’eccezione come secondo parametro al logger.

logger.error("Errore durante l'elaborazione della richiesta", ex);

Usate identificatori univoci (correlazione degli eventi)

Nei sistemi di grandi dimensioni è utile assegnare a ogni richiesta, utente o operazione un identificatore univoco. Questo aiuta a “ricucire” eventi provenienti da parti diverse del sistema.

logger.info("Elaborazione dell'ordine avviata: orderId={}", orderId);
logger.info("Ordine elaborato con successo: orderId={}", orderId);

Non registrate tutto nei log

Se i log sono troppo verbosi — diventano inutili. Non registrate ogni riga di codice, altrimenti sarà impossibile trovare le informazioni necessarie.

Formattate i messaggi in modo chiaro

Scrivete messaggi in modo che siano comprensibili non solo all’autore del codice, ma anche a chi leggerà i log tra sei mesi. Evitate sigle, abbreviazioni oscure e “battute interne”.

5. Pratica: configurare formato del log e livelli

Esempio di configurazione del formato in Log4j2 (log4j2.xml)

<Configuration>
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>

Cosa significa?

• %d{...} — timestamp dell’evento.
• %-5level — livello (ERROR, INFO ecc.).
• %logger{36} — nome del logger (di solito la classe).
• %msg — il messaggio.

Esempio di codice con diversi livelli di log (SLF4J)

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LogDemo {
    private static final Logger logger = LoggerFactory.getLogger(LogDemo.class);

    public static void main(String[] args) {
        logger.info("Applicazione avviata");
        logger.debug("Valore della variabile x: {}", 42);

        try {
            throw new IllegalArgumentException("Ahi ahi!");
            // ...
        } catch (Exception ex) {
            logger.error("Si è verificato un errore all'avvio", ex);
        }
    }
}

Dimostrazione della differenza fra i livelli

Se nelle impostazioni del logger è impostato il livello INFO, i messaggi con livello DEBUG e inferiori non verranno stampati. Provate a cambiare il livello a debug nel config — vedrete più dettagli.

Errori tipici

Errore n. 1: Concatenazione di stringhe nei log. Molto spesso i principianti scrivono così:

logger.debug("Utente: " + user.getName() + ", ruolo: " + user.getRole());

Di conseguenza, anche con il livello DEBUG disattivato, queste stringhe verranno costruite, con carico inutile. Usate i parametri!

Errore n. 2: Registrazione senza stack dell’eccezione. Scrivono solo il messaggio:

logger.error("Errore: " + ex.getMessage());

Alla fine nei log non c’è informazione su dove esattamente è avvenuto l’errore. Passate l’eccezione come secondo parametro!

Errore n. 3: Registrare tutto al livello ERROR. Se tutto è rosso — niente è rosso. Usate i livelli per lo scopo previsto, altrimenti gli errori importanti si perderanno tra le “piccolezze”.

Errore n. 4: Registrazione di dati sensibili. Non scrivete mai nei log password, token, numeri di carta. Anche se sembra che nessuno li vedrà, la vita ama le sorprese.

Errore n. 5: Messaggi incomprensibili. Se un messaggio di log appare come “ERR42: fail”, fra un mese non ricorderete cosa significava. Scrivete in modo chiaro e dettagliato.

Errore n. 6: Assenza di identificatori univoci. In sistemi complessi, senza orderId, userId e altri identificatori non riuscirete a “ricucire” gli eventi e a capire cosa sia successo a un particolare utente o ordine.