Come Personalizzare il Logger in Fastify
Intro
Fastify usa pino come logger, uno dei più performanti logger per Node.js.
Quindi generalmente per personalizzare il logger di Fastify, si applicano gli stessi concetti per personalizzare pino, ma con qualche eccezione che vedremo in questo articolo.
Per questo articolo è stato usato Node.js v20.13.1
Abilitare il logger
Di default il logger di Fastify è disabilitato, per abilitarlo basta impostarlo a true quando si inizializza Fastify.
const fastify = Fastify({
logger: true
})
Scriviamo il primo log
Per vedere il primo esempio di log creiamo un semplice progetto Fastify, che poi useremo per tutti gli altri esempi che vedremo in questo articolo.
Creiamo il progetto Fastify
Creiamo ed entriamo nella cartella del progetto
mkdir my-logger
cd my-logger
Installiamo Fastify nel progetto
npm install fastify
Questo il contenuto del file package.json generato:
{
"dependencies": {
"fastify": "^4.28.1"
}
}
Creiamo il file index.js
// importa Fastify
const Fastify = require('fastify')
// inizializza Fastify
const fastify = Fastify({
logger: true // abilita il logger (disabilitato di default)
})
// inizia a loggare
fastify.log.info('Hello Log!')
Non abbiamo avviato alcun server, abbiamo solo inizializzato Fastify, e questo è sufficiente per iniziare a loggare.
Eseguiamo il file con il comando:
node server
Come output otterremo un oggetto simile a questo:
{"level":30,"time":1721369918925,"pid":85758,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello World!"}
Formattiamolo meglio per analizzarlo
{
"level":30, // 30 rappresenta il livello info dovuto da: fastify.log.info
"time":1721369918925, // Unix time in millisecondi ( epoch time )
"pid":85758, // id del processo ( equivlente a process.pid )
"hostname":"Manuels-MacBook-Pro.local", // il nome host del sistema operativo. ( equivlente a require('os').hostname() )
"msg":"Hello World!" // la stringa che abbiamo loggato
}
Vediamo che dalla nostra semplice chiamata di log:
fastify.log.info('Hello Log!')
Solo "msg" è effettivamente quello che abbiamo scritto noi, tutti gli altri campi sono stati aggiunti da Pino, e verranno aggiunti per ogni chiamata al logger.
Personalizziamo il Logger
Abbiamo visto che di default quando facciamo una chiamata al logger viene loggato un oggetto JSON in cui il nostro messaggio viene messo come valore del campo "msg".
Ma vengono anche aggiunti da Pino i campi:
"level"
"time"
"pid"
"hostname"
In questa sezione vedremo come personalizzarli uno ad uno.
level
Prima di personalizzare il campo "level" vediamo un pò come funziona.
In Pino esistono diversi livelli di log:
"fatal" | "error" | "warn" | "info" | "debug" | "trace".
Per ogni livello esiste il suo corrispondente metodo:
const Fastify = require('fastify')
const fastify = Fastify({
logger: true
})
fastify.log.fatal('Hello fatal!')
fastify.log.error('Hello error!')
fastify.log.warn('Hello warn!')
fastify.log.info('Hello info!')
fastify.log.debug('Hello debug!')
fastify.log.trace('Hello trace!')
Il codice di sopra genererà il seguente output:
{"level":60,"time":1722405654790,"pid":57113,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello fatal!"}
{"level":50,"time":1722405654790,"pid":57113,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello error!"}
{"level":40,"time":1722405654790,"pid":57113,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello warn!"}
{"level":30,"time":1722405654790,"pid":57113,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello info!"}
Ma c'è qualcosa di strano, perché dal codice abbiamo chiamato il logger 6 volte, ma ne sono stati generati solo 4?:
"Hello fatal!"
"Hello error!"
"Hello warn!"
"Hello info!"
Mancano all'appello:
"Hello debug!"
"Hello trace!"
Dove sono finiti?
Pino associa ad ogni livello un valore numerico:
"fatal" = 60
"error" = 50
"warn" = 40
"info" = 30
"debug" = 20
"trace" = 10
Che possiamo vedere nel campo "level" dei log generati.
Di default vengono scartati i log sotto il livello 30, ovvero "info".
Per cambiare questo default e vedere i log di tutti i livelli, bisogna impostare il campo level del logger in questo modo:
const fastify = Fastify({
logger: {
level: 'trace'
}
})
Ora vediamo che ci sono tutti e 6 i log:
{"level":60,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello fatal!"}
{"level":50,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello error!"}
{"level":40,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello warn!"}
{"level":30,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello info!"}
{"level":20,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello debug!"}
{"level":10,"time":1722406770355,"pid":57832,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello trace!"}
Ora che abbiamo capito come funziona il campo "level", vediamo come personalizzarlo:
const fastify = Fastify({
logger: {
formatters: {
level (label, number) {
// questi campi verranno sostituiti al campo "level" di default
return {
myLevel: `${label}-${number}`,
levelName: label,
levelNumber: number
}
}
}
}
})
Ora i log generati saranno in questo formato:
{"myLevel":"fatal-60","levelName":"fatal","levelNumber":60,"time":1722576879835,"pid":90770,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello fatal!"}
{"myLevel":"error-50","levelName":"error","levelNumber":50,"time":1722576879835,"pid":90770,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello error!"}
{"myLevel":"warn-40","levelName":"warn","levelNumber":40,"time":1722576879835,"pid":90770,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello warn!"}
{"myLevel":"info-30","levelName":"info","levelNumber":30,"time":1722576879835,"pid":90770,"hostname":"Manuels-MacBook-Pro.local","msg":"Hello info!"}
Come possiamo vedere dai log, ora al posto del campo "level" ne troviamo altri 3:
"myLevel"
"levelName"
"levelNumber"
time
Si può personalizzare il campo time impostando il campo "timestamp" nel seguente modo:
const Fastify = require('fastify')
const pino = require('pino')
const fastify = Fastify({
logger: {
timestamp: pino.stdTimeFunctions.isoTime, // converte da epoch time a ISO time
}
})
fastify.log.info('Hello info!')
{
"level":30,
"time":"2024-07-18T06:48:52.040Z", // ISO Time
"pid":19929,
"hostname":"Manuels-MacBook-Pro.local",
"msg":"Hello info"
}
Pino ci mette a disposizione le seguenti funzioni per la formattazione del "timestamp":
pino.stdTimeFunctions.epochTime
: Milliseconds since Unix epoch (Default)pino.stdTimeFunctions.unixTime
: Seconds since Unix epochpino.stdTimeFunctions.nullTime
: Clears timestamp property (Used whentimestamp: false
)pino.stdTimeFunctions.isoTime
: ISO 8601-formatted time in UTC
Dalla documentazione ufficiale: Pino stdTimeFunctions
pid e hostname
Per personalizzare i campi "pid" e "hostname" bisogna personalizzare i bindings.
I bindings sono dati aggiuntivi che possono essere associati ad un logger per essere inclusi in tutti i log generati da quel logger. Questi dati vengono utilizzati per arricchire le informazioni dei log senza dover specificare manualmente queste informazioni ogni volta che si effettua una chiamata di log.
Di default Pino logger aggiunge nei bindings: "pid" e "hostname", quindi per rimuoverli ed aggiungere campi a nostro piacimento dobbiamo modificare i bindings in questo modo:
const Fastify = require('fastify')
const os = require('os')
const fastify = Fastify({
logger: {
formatters: {
bindings: (bindings) => {
return {
osMachine: os.machine(),
osType: os.type()
};
},
},
}
})
fastify.log.info('Hello info!')
{
"level":30,
"time":1721283756521,
"osMachine":"arm64",
"osType":"Darwin",
"msg":"Hello info!"
}
Vediamo che "pid" e "hostname" non ci sono più, ma al loro posto ci sono "osMachine" e "osType".
Invece di sostituire "pid" e "hostname" possiamo anche tenerli ed aggiungere campi in questo modo:
const fastify = Fastify({
logger: {
formatters: {
bindings: (bindings) => {
return {
pid: bindings.pid,
hostname: bindings.hostname,
osMachine: os.machine(),
osType: os.type()
};
},
},
}
})
fastify.log.info('Hello info!')
{
"level":30,
"time":1722577623975,
"pid":91371,
"hostname":"Manuels-MacBook-Pro.local",
"osMachine":"arm64",
"osType":"Darwin",
"msg":"Hello info!"
}
Cos'è il Request Logger?
Fino ad ora abbiamo usato il logger di Fastify ma senza mai avviare un server.
Fastify ci mette a disposizione una feature utilissima che si chiama appunto "Request Logger".
Ora con qualche esempio pratico vedremo come funziona e come personalizzarlo.
Creiamo il server
const Fastify = require('fastify')
const fastify = Fastify({
logger: true
})
// Dichiara la rotta GET /
fastify.get('/', async function handler (request, reply) {
fastify.log.info('Fastify logger!')
// notare che viene usato request.log al posto di fastify.log
// al contrario degli esempi precedenti
request.log.info('Request logger!')
return { hello: 'world' }
})
// Avvia il server sulla porta 3000
fastify.listen({ port: 3000 }, (err) => {
if (err) {
fastify.log.error(err)
process.exit(1)
}
})
In questo server abbiamo definito solo una rotta GET "/" che:
logga la stringa "Fastify logger!" (con fastify.log)
logga la stringa "Request logger!" (con request.log)
ritorna come risposta l'oggetto: { hello: 'world' }
Da notare che per il primo log viene usato "fastify.log" per il secondo "request.log". Poi vedremo con un esempio qual'è la differenza tra i due.
Avviamo il server con:
node server
All'avvio del server vedremo dei log auto generati da Fastify del genere:
{"level":30,"time":1720591420640,"pid":69286,"hostname":"Manuels-MacBook-Pro.local","msg":"Server listening at http://127.0.0.1:3000"}
{"level":30,"time":1720591420643,"pid":69286,"hostname":"Manuels-MacBook-Pro.local","msg":"Server listening at http://[::1]:3000"}
Prima chiamata HTTP
Ora proviamo a fare una chiamata HTTP, ad esempio con Postman alla nostra unica rotta appena creata.
Questa chiamata ha generato 4 log:
// auto generato da Fastify (quando riceve una richiesta HTTP)
{
"level":30,
"time":1720678823876,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/",
"hostname":"127.0.0.1:3000",
"remoteAddress":"127.0.0.1",
"remotePort":63548
},
"msg":"incoming request"
}
// generato da noi con fastify.log.info('Fastify logger!')
{
"level":30,
"time":1720678823877,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"msg":"Fastify logger!"
}
// generato da noi con request.log.info('Request logger!')
{
"level":30,
"time":1720678823877,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"msg":"Request logger!"
}
// auto generato da Fastify (quando invia una risposta HTTP)
{
"level":30,
"time":1720678823880,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"res":{
"statusCode":200
},
"responseTime":3.9882499873638153,
"msg":"request completed"
}
Tra i quattro log c'è un intruso, riesci a vederlo?
L'intruso è il secondo: "Fastify logger!"
Infatti possiamo vedere che è l'unico che non ha il "reqId". Non ha il "reqId" perché è l'unico a non essere stato generato dal request logger.
Fastify per ogni richiesta genera un "reqId" utile per collegare tutti i log a quella specifica richiesta, nel nostro caso:
"incoming request" è stato generato da Fastify alla ricezione della richiesta, e per questa richiesta è stato creato un id univoco "reqId":"req-1".
"Fastify logger!" è stato generato da noi con fastify.log.info('Fastify logger!'), ma siccome abbiamo usato fastify.log, questo log non farà parte del contesto della richiesta, quindi "reqId":"req-1" non verrà loggato.
"Request logger!" è stato generato da noi con request.log.info('Request logger!'), in questo caso siccome abbiamo usato request.log, questo log farà parte del contesto della richiesta quindi "reqId":"req-1" verrà loggato.
"request completed" è stato generato da Fastify quando la richiesta è terminata e la risposta è stata inviata.
Disabilitare il request logger
const app = Fastify({
disableRequestLogging: true, // disabilita il request logger
logger: true
})
Basta impostare disableRequestLogging a true per non far generare a Fastify in automatico i log alla ricezione della richiesta ed all'invio della risposta.
Vediamo l'esempio precedente con il request logger disabilitato:
const Fastify = require('fastify')
const fastify = Fastify({
disableRequestLogging: true, // disabilita il request logger
logger: true
})
// Dichiara la rotta GET /
fastify.get('/', async function handler (request, reply) {
fastify.log.info('Fastify logger!') // viene loggato
request.log.info('Request logger!') // viene comunque loggato
return { hello: 'world' }
})
// Avvia il server sulla porta 3000
fastify.listen({ port: 3000 }, (err) => {
if (err) {
fastify.log.error(err)
process.exit(1)
}
})
Avviamo il server:
node server
{"level":30,"time":1722320649945,"pid":20123,"hostname":"Manuels-MacBook-Pro.local","msg":"Server listening at http://[::1]:3000"}
{"level":30,"time":1722320649947,"pid":20123,"hostname":"Manuels-MacBook-Pro.local","msg":"Server listening at http://127.0.0.1:3000"}
I log automatici all'avvio del server vengono comunque generati.
Facciamo ancora la chiamata HTTP con Postman:
{"level":30,"time":1722320840449,"pid":20123,"hostname":"Manuels-MacBook-Pro.local","msg":"Fastify logger!"}
{"level":30,"time":1722320840449,"pid":20123,"hostname":"Manuels-MacBook-Pro.local","reqId":"req-1","msg":"Request logger!"}
Vediamo che ora sono solo 2 i log, mancano quelli auto generati da Fastify:
"incoming request"
"request completed"
Ma il request logger che abbiamo invocato manualmente con:
request.log.info('Request logger!')
Viene comunque loggato.
Personalizziamo il Request Logger
Il Request Logger viene usato nei seguenti casi:
chiamato esplicitamente con il metodo: "request.log"
chiamato automaticamente da Fastify ad ogni nuova richiesta HTTP ricevuta
chiamato automaticamente da Fastify ad ogni risposta HTTP inviata
chiamato automaticamente da Fastify ad ogni eccezione generata dentro una rotta (non lo abbiamo ancora visto ma lo vedremo dopo)
Rivediamoli uno ad uno:
// chiamato esplicitamente con il metodo: "request.log"
{
"level":30,
"time":1720678823877,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"msg":"Request logger!"
}
// chiamato automaticamente da Fastify ad ogni nuova richiesta HTTP ricevuta
{
"level":30,
"time":1720678823876,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/",
"hostname":"127.0.0.1:3000",
"remoteAddress":"127.0.0.1",
"remotePort":63548
},
"msg":"incoming request"
}
// chiamato automaticamente da Fastify ad ogni risposta HTTP inviata
{
"level":30,
"time":1720678823880,
"pid":2292,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"res":{
"statusCode":200
},
"responseTime":3.9882499873638153,
"msg":"request completed"
}
// chiamato automaticamente da Fastify ad ogni eccezione generata dentro una rotta
{
"level":50,
"time":1720766398542,
"pid":40069,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/",
"hostname":"127.0.0.1:3000",
"remoteAddress":"127.0.0.1",
"remotePort":54858
},
"res":{
"statusCode":500
},
"err":{
"type":"Error",
"message":"Boom!",
"stack":"Error: Boom!\n at Object..."
},
"msg":"Boom!"
}
Quindi possiamo vedere che dal Request Logger vengono aggiunti i seguenti campi:
"reqId"
"req"
"res"
"err"
In questa sezione vedremo come personalizzarli uno ad uno.
reqId
La prima cosa che possiamo personalizzare del request logger è il "reqId", con il metodo: genReqId
let currentId = 1
const fastify = Fastify({
logger: true,
genReqId: (req) => {
return `my-custom-id-${currentId++}`
}
})
{
"level":30,
"time":1722580879611,
"pid":93284,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"my-custom-id-1", // Generato dal nostro genReqId
"msg":"Request logger!"
}
req e res
Come facciamo a personalizzare gli oggetti "req" e "res" che vengono loggati? Per esempio aggiungere o rimuovere campi?
Si usa l'oggetto serializers per questo:
const fastify = Fastify({
logger: {
serializers: {
req (request) { // in req vogliamo solo: method e url
return {
method: request.method,
url: request.url,
};
},
res (reply) { // in res vogliamo: method, url e statusCode
return {
method: reply.request.method,
url: reply.request.url,
statusCode: reply.statusCode
}
},
}
}
})
// ora req contiene solo method e url
// invece che il default: method, url, hostname, remoteAddress, remotePort
{
"level":30,
"time":1720765071638,
"pid":38418,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/"
},
"msg":"incoming request"
}
// questo log non è affetto dal serializers perchè non contiene ne req ne res
{
"level":30,
"time":1720765071638,
"pid":38418,
"hostname":"Manuels-MacBook-Pro.local",
"msg":"Fastify logger!"
}
// anche questo log non è affetto dal serializers perchè non contiene ne req ne res
{
"level":30,
"time":1720765071638,
"pid":38418,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"msg":"Request logger!"
}
// ora res contiene: method, url, statusCode
// invece che il default: statusCode
{
"level":30,
"time":1720765071640,
"pid":38418,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"res":{
"method":"GET",
"url":"/",
"statusCode":200
},
"responseTime":2.362499952316284,
"msg":"request completed"
}
err
Se dentro una rotta viene generata un eccezione, Fastify la gestisce e la logga per noi in automatico, vediamo un esempio.
Generiamo un eccezione nella nostra rotta:
fastify.get('/', async function handler (request, reply) {
throw Error('Boom!') // Questo genererà l'errore
fastify.log.info('Fastify logger!')
request.log.info('Request logger!')
return { hello: 'world' }
})
Se proviamo a fare la chiamata HTTP a GET "/" vedremo generato questo log:
{
"level":50,
"time":1720766398542,
"pid":40069,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/",
"hostname":"127.0.0.1:3000",
"remoteAddress":"127.0.0.1",
"remotePort":54858
},
"res":{
"statusCode":500
},
// fastify di default logga un oggetto err, con dentro: type, message e stack
"err":{
"type":"Error",
"message":"Boom!",
"stack":"Error: Boom!\n at Object.handler (/Users/manuelsalinardi/..."
},
"msg":"Boom!"
}
Vediamo che per l'errore, Fastify genera un log con dentro l'oggetto "err".
Se non volessimo loggare lo stack per motivi di sicurezza?
Anche in questo caso possiamo personalizzare l'oggetto "err" come abbiamo fatto con gli oggetti "req" e "res", usando l'oggetto serializers:
const fastify = Fastify({
logger: {
serializers: {
req (request) {
return {
method: request.method,
url: request.url,
};
},
res (reply) {
return {
method: reply.request.method,
url: reply.request.url,
statusCode: reply.statusCode
}
},
// qui personalizziamo l'oggetto err
err (error) {
return {
type: error.name,
message: error.message,
}
}
}
}
})
Questo il log generato:
{
"level":50,
"time":1720767139181,
"pid":40774,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-1",
"req":{
"method":"GET",
"url":"/"
},
"res":{
"method":"GET",
"url":"/",
"statusCode":500
},
// ora stack non è più presente
"err":{
"type":"Error",
"message":"Boom!"
},
"msg":"Boom!"
}
Aggiungere nuovi campi al Request Logger
Fastify ci aiuta a mettere in relazione tra loro tutti i log di una specifica richiesta tramite il campo "reqId".
Abbiamo visto che "reqId" lo possiamo anche personalizzare, ma come facciamo ad aggiungere un altro campo simile a "reqId", ma scelto a nostro piacimento?
Ad esempio vogliamo aggiungere al request logger il campo "user", che ci viene passato come parametro nella URL da chi fa la chiamata HTTP.
Per fare questo bisogna chiamare il metodo di Fastify setChildLoggerFactory:
const Fastify = require('fastify')
const fastify = Fastify({
logger: true,
})
// aggiunge campi al Request Logger
fastify.setChildLoggerFactory((logger, bindings, opts, rawReq) => {
// recupera user dalla URL
const urlString = rawReq.url || ''
const queryString = urlString.split('?')[1]
const searchParams = new URLSearchParams(queryString)
const user = searchParams.get('user')
// aggiunge user ai bindings
bindings.user = user
return logger.child(bindings, opts)
})
// dichiara la rotta
fastify.get('/', async function handler (request, reply) {
request.log.info('Request logger!')
return { hello: 'world' }
})
// avvia il server
fastify.listen({ port: 3000 }, (err) => {
if (err) {
fastify.log.error(err)
process.exit(1)
}
})
Ora facciamo una chiamata HTTP con il parametro user:
Vedremo dei log del genere:
{
"level":30,
"time":1722583839646,
"pid":95780,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-2",
"user":"manuel", // nuovo campo user
"req":{
"method":"GET",
"url":"/?user=manuel",
"hostname":"127.0.0.1:3000",
"remoteAddress":"127.0.0.1",
"remotePort":52098
},
"msg":"incoming request"
}{
"level":30,
"time":1722583839646,
"pid":95780,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-2",
"user":"manuel", // nuovo campo user
"msg":"Request logger!"
}{
"level":30,
"time":1722583839648,
"pid":95780,
"hostname":"Manuels-MacBook-Pro.local",
"reqId":"req-2",
"user":"manuel", // nuovo campo user
"res":{
"statusCode":200
},
"responseTime":1.4203753471374512,
"msg":"request completed"
}
Ora il Request Logger oltre al "reqId" avrà anche il nuovo campo "user".
Manuel Salinardi
Subscribe to my newsletter
Read articles from Manuel Salinardi directly inside your inbox. Subscribe to the newsletter, and don't miss out.
Written by