前面幾章，大致上把原本活動訂票管理系統的主要功能完成了。接著，會針對一些非功能性需求來作處理。今天主要會來實做結構化 logger。
logger 在系統中的作用，主要是用來紀錄系統發生過的事件。在正式環境中，往往一系列的事件會一起發生，假設系統沒有一個標準的格式。那會造成紀錄難以讀取，容易遺漏的問題。因此，標準化的紀錄格式是一個對蒐集與解析 logger 的人或是服務能夠提昇可觀測性的重要一步。
要能紀錄一個事件，關鍵要素有以下幾點：
今天會透過 pino 這個套件來實做這件事情。
pnpm i -S nest-pino pino-http
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import { ValidationPipe } from '@nestjs/common';
import { Logger } from 'nestjs-pino';
async function bootstrap() {
const app = await NestFactory.create(AppModule, {
bufferLogs: true,
});
app.useLogger(app.get(Logger));
app.useGlobalPipes(new ValidationPipe({
whitelist: true,
transform: true,
}))
await app.listen(3000);
}
bootstrap();
這個設定是當整個 app 被 NestFactory 建立出來後才取出 pino logger 當作全域的 logger 。這個設定要能正常運作要有一個前提，就是 NestFactory 建制要能成功且正常運作。假設在建制過程失敗，則 logger 無法啟用，沒有資訊。
這個問題的解法，在下一章的 graceful shutdown 部份，會做出一個解法。今天先專注在於 pino logger 的設定。
在 imports 的欄位加入以下設定
LoggerModule.forRootAsync({
useFactory: async () => {
return {
pinoHttp: {
autoLogging: false,
base: null,
quietReqLogger: true,
genReqId: (request: Request) => request.headers['x-correlation-id'] || crypto.randomUUID(),
level: 'info',
formatters: {
level (label) {
return {level: label }
}
}
},
}
}
}),
在 pinoHttp 這個欄位，代表示透過 http request 進來的 logger 都套用以這個欄位的設定。
在 pinoHttp 中，有幾個比較重要的欄位在以下作個別說明：
import { CallHandler, ExecutionContext, HttpException, Injectable, Logger, NestInterceptor } from '@nestjs/common';
import { Request, Response } from 'express';
import { catchError, Observable, tap, throwError } from 'rxjs';
@Injectable()
export class LoggerInterceptor implements NestInterceptor {
private readonly logger = new Logger(LoggerInterceptor.name);
intercept(context: ExecutionContext, next: CallHandler<unknown>): Observable<unknown> | Promise<Observable<unknown>> {
const request: Request = context.switchToHttp().getRequest();
const userAgent = request.get('user-agent') ?? '';
const { ip, method, path: url } = request;
this.logger.log({method, url, userAgent, ip, name: context.getClass().name, handler: context.getHandler().name, type: 'Invoke' });
const now = Date.now();
return next.handle().pipe(
tap((res) => {
const response = context.switchToHttp().getResponse();
const { statusCode } = response;
const contentLength = response.get('content-length');
this.logger.log({
method, url, statusCode, contentLength, userAgent,
requestInMillis: Date.now() - now,
res
});
}),
catchError((error: unknown) => {
const response: Response = context.switchToHttp().getResponse();
const httpError = error as HttpException;
const statusCode = httpError.getStatus() ?? response.statusCode ?? undefined;
this.logger.error({
method, url, statusCode, userAgent, ip, class: context.getClass().name,
handler: context.getHandler().name,
requestInMillis: Date.now() - now
});
return throwError(() => error);
})
);
}
}
故意註冊一個已經存在的 email 來看看錯誤的 logger
logger 如下：
可以看到基本上，上述所講的 reqId 與 logger level 以及相對應的資訊，都可以從 以相同格式顯示出來。這樣在後續的 debug 與追查相關事件就能方便找出可能的原因。
當其他 Service 要引用該 logger 時，只需要使用原本的 nestjs/common 內的 Logger 類別，如下
好處是在全域配置之後，所有其他的 Logger 都是自動在建制時，被套用為 pinoLoger 。也因此，剛剛作的 logger 設定都能自動被套用，不用額外作其他複寫之類。
這也是 nestjs 的 DI container 的強大之處。
結構化 logger 雖然算是非功能性的需求，然而在日常開發運維的系統上十分重要。可以說是能簡化尋找 bug ，以及找尋效能問題的基礎。因此，使用相對標準的設定與彈性的套件很重要。
這邊使用的 pino logger 算是近年來 nodejs 相對比較輕量化的 logger ， 與 winston 與 morgan 等成熟的套件來說， pino 優點在於其套件 size 小，與配置上的簡單。當然有人說 pino 強化了一些序列化的效能，也許是因為其本身的 size 沒這樣大，所以載入記憶體時的耗損沒這樣大。
基本上，如果是使用 nodejs 開發，最常使用就是 pino, winston, morgan 這三種。
另外，有一點要注意的是， logger 不代表回應的值。這看似理所當然的事情，在我過去待過得公司，還是會有人把所有 logger 上的資訊直接往外拋。這後來雖然有透過 sonarcube 來 scan 的來抓出不當的寫法。但實務上比較踏實的作法就是，開發者還是要有這樣的概念 - logger event 是用來觀測系統，理應跟回應分開作處理。
iThome鐵人賽
看影片追技術