以下の記事で書いたように、ユビーではNestJSを利用したモジュラモノリスなシステムの構築を進めています。
その際に得られた知見として今回は構造化ロギングについて紹介します。
やりたいこと
まず、実現したいのは以下のようなことです。
- ユビーではGCPのCloud Loggingにログを出力しているため、Cloud Loggingに合わせたかたちでログを出力したい
- Cloud LoggingはJSONによる構造化ログをサポートしている
- 出力するJSONのフィールドはいくつか特別扱いされるものがある。例えば
severityやmessageなど - NestJSにおいてこれらに対応したかたちでログを出力したい
- ローカルでの開発時は見やすいかたちでコンソールに出力したい
- ロガーはNestJS標準のロガーを使いたい（ただしロガーの実装はカスタムロガーにしてもよい）
例えば以下のような出力になります。
const logger = new Logger("bootstrap");
logger.log("Hello NestJS!", { hello: "world" });
logger.warn("This is warning logs");
logger.error("This is error logs", { code: "ERROR_CODE" });
Text
JSON
カスタムロガーの実装
NestJSのロガーはデフォルトでは構造化ログをサポートしていません。しかし、カスタムロガーを実装することで出力の形式などを自由に変更することができます。
カスタムロガーを実装することで本番ではJSON、ローカルではテキスト形式で出力するようにします。色々と省略していますが、実装としての雰囲気は概ねこんな感じです。
import { LoggerService } from "@nestjs/common";
export class StructuredLogger implements LoggerService {
private format: "json" | "text";
constructor(options: { format: "json" | "text" }) {
this.format = options.format;
}
log(message: any, ...optionalParams: any[]): any {
this.print({ message, params: optionalParams, severity: "info" });
}
warn(message: any, ...optionalParams: any[]): any {
this.print({ message, params: optionalParams, severity: "warn" });
}
error(message: any, ...optionalParams: any[]): any {
this.print({ message, params: optionalParams, severity: "error" });
}
private print({ message: params, severity }: { message: string; params: any[]; severity: string }): void {
switch (this.format) {
case "json":
this.printJson({ message, params, severity });
break;
case "text":
this.printText({ message, params, severity });
break;
}
}
private printJson({ message: params, severity }: { message: string; params: any[]; severity: string }): void {
const output = JSON.stringify({ message, severity, params });
process.stdout.write(output);
}
private printText({ message: params, severity }: { message: string; params: any[]; severity: string }): void {
// ...
}
}
初期化するときにフォーマットを受け取ってそれを見て出力する形式を変更するだけです。出力する部分は pino などのライブラリを使ってもよいと思いますが、ロガーのインタフェースはNestJSのLoggerを使うため、カスタムロガーの内部だけで pino を使ってもあまりメリットを感じなかったので今回は出力部分も自前で実装しました。
また、ログレベルを severity という名前にしていますが、これはCloud Loggingの規約で、severity という名前のフィールドで出力することでCloud Logging側でアイコンを変えたり絞り込みしやすくなるなどの利点があるのでこれは絶対にやっておきましょう。
一点注意点として、Cloud Logging では info にあたるログレベルが NestJS だと log になります。なのでカスタムロガーを実装するときに log メソッドだけ severity を info に変更しておきましょう。
log(message: any, ...optionalParams: any[]): any {
// logでなくinfoにする
this.print({ message, params: optionalParams, severity: "info" });
}
カスタムロガーの実装のTips
カスタムロガーを作る時に得られた知見などを紹介しおきます。
基本的にはConsoleLoggerをベースにする
実装はNestJSのデフォルトロガー実装である ConsoleLogger をベースにするとよいです。継承して必要な部分だけ上書きしてもよいと思います。ただ私の場合は最初継承して上書きしていて、気づいたらほぼ全部上書きすることになったので途中で継承するのをやめました…。
メソッドのインタフェースは変更できない
NestJSのカスタムロガーは LoggerService というインターフェースを満たすように作ります。基本的には以下のメソッドが実装されてればOKです。
log(message: any, ...optionalParams: any[]): any;
error(message: any, ...optionalParams: any[]): any;
warn(message: any, ...optionalParams: any[]): any;
このメソッドの引数を自由に変更することはできません。例えば error で Error のインスタンスを取れるようにしたいと思い以下のようにすることはできません。
error(message: string, { err }: { err: Error }): any;
なぜならここで定義するカスタムエラー class はそのまま利用されるのでなく、NestJS標準の Logger を通して実行されるからです。
import { Logger } from "@nestjs/common";
//...
function bootstrap() {
const app = await NestFactory.create(AppModule);
app.useLogger(new CustomLogger());
// CustomLoggerのlogメソッドが直接利用されるわけではない
// Loggerのメソッドを通してCustomLoggerのメソッドが呼ばれる
const logger = new Logger();
logger.log("hello logger!");
//...
}
後述するように、NestJSのロガーは独特な引数で値が渡ってくるケースがあって、引数のインターフェースを変えたくなりますがそれは無理なので諦めましょう。
入力のcontextに対応する
NestJSのログには context という概念があります。ロガーを作る時、基本的には以下のように定義することが多いと思います。
class FooService {
private readonly logger = new Logger(FooService.name);
}
このコンストラクタに渡す名前が context です。デフォルトのロガーだと黄色でブラケットに囲まれて出力されます。
Cloud Loggingに出力する構造化ロギングにおいて、この context もちゃんと context という名前のフィールドで出力しておきたいので適切に取得する必要があります。しかし、このcontext はロガーの関数にはそのまま渡ってくるわけではありません。
log(message: any, ...optionalParams: any[])
というメソッドの引数の optionalParams の最後の要素が文字列だったらそれを context とみなします。ConsoleLogger では以下のような実装になっています。
こんな感じで抽出して構造化ログの出力関数にわたします。
log(message: any, ...optionalParams: any[]): any {
const { messages, context } = this.getContextAndMessagesToPrint([ message, ...optionalParams ]);
this.print({ messages, context, severity: "info" });
}
パラメータ分けて入力してほしいですねぇ…。
logger.errorでstacktraceの出力に対応する
logger.error の第二引数に stacktrace っぽいものが渡ってきたらログとは別に出力する、という仕様があります。例えばこんな感じで使います。
async function bootstrap() {
const logger = new Logger("bootstrap");
const err = new Error("err!");
logger.error(err.message, err.stack);
//...
}
これは例えばNestJSデフォルトの例外処理である BaseExceptionFilter で使われています。
アプリケーション内でハンドリングされていない例外が発生したときに stacktrace がログにでるのはこの仕組みによるものです。
stacktraceは単なる文字列であり、型だけでは判定できないので、以下のような正規表現でstacktraceかどうかを判定しています。
パラメータ分けて入力してほしいですねぇ…。
なお、Cloud Loggingにおいては、stacktraceは stack_trace という名前にするとよさそうなのでちゃんと判定して出力しておくとよさそうです。
まとめ
NestJSにおいて構造化ロギングを実現するためのカスタムロガーの実装やそのときの注意点などについて書きました。構造化ロギング以外にも、リクエストごとに一意なidをログに付与したいなどの要件を考えるとカスタムロガーの実装は必須になるので、カスタムロガーを実装したくなったときにこの話を思い出してみてください（それはそれとしてもう少しNestJSのデフォルトロガーがいい感じになると嬉しいのですが…。）
ユビーではNestJSを使ったアプリケーションがたくさんあるので興味あるかたはぜひ一度お話しましょう！お待ちしております！
Discussion