NestjsでLogging - winstonを使ってファイルに残す & SQLクエリもちゃんとLogging

はじめに

Nestjsを使い始めてから、なんとなく書き味が分かってきたのでドキュメント化します。
最初はログです。実行したSQLクエリをログファイルに残すのがゴールです。

リポジトリ：https://github.com/michihiko-karino/nestjs-query-logger-sample

TableOfContents

• NestjsのLoggingのやり方
• 公式Docの最後でwinstonが紹介されてるので使ってみた
• SQLクエリもログとしてファイルに残したいね。TypeORMのLoggerを使ってみた

NestjsのLoggingのやり方

公式Doc：https://docs.nestjs.com/techniques/logger

公式Docを要約しますと

• @nestjs/commonのLoggerクラスがビルトインされています。
• カスタマイズしたい場合は、LoggerServiceインタフェースを実装したクラスを準備してください
• 本番環境でそれぞれの要件に沿う高度なロギングが必要となる場合はwinstonのようなロガーライブラリをNestjsと組み合わせて使うことも出来ます

公式Docの示す通り実装すれば、ひとまずLoggingできることが分かりました。

公式Docの最後でwinstonが紹介されてるので使ってみた

次に、ログをファイルに残すことを考えてみます。公式でも紹介されているwinstonを使ってみます

import * as winston from 'winston';
import { LoggerService } from '@nestjs/common';

// https://github.com/winstonjs/winston
export class Logger implements LoggerService {
  logger: winston.Logger;

  constructor() {
    const fileFormat = winston.format.combine(
      winston.format.timestamp(),
      winston.format.json(),
    );

    // levelにdebugを指定することでdebug以上のLevelのログが出力される
    // https://github.com/winstonjs/winston#logging
    const logger = winston.createLogger({
      // winstonの機能として、複数のtransport先を指定することができます。
      // 今回の場合であれば、ConsoleとFile両方に出力しています
      transports: [
        new winston.transports.Console({
          level: 'debug',
          format: winston.format.combine(
            winston.format.colorize(),
            winston.format.simple(),
          ),
        }),
        // またFile出力で、「エラーログだけで別ファイルに残したい」などの要件は、levelを指定することで実現できます
        new winston.transports.File({
          filename: 'log/error.log',
          level: 'error',
          format: fileFormat,
        }),
        new winston.transports.File({
          filename: 'log/combined.log',
          level: 'debug',
          format: fileFormat,
        }),
      ],
    });

    this.logger = logger;
  }

  log(message: string) {
    this.logger.log({
      level: 'info',
      message: `${message}`,
    });
  }

  error(message: string, trace: string) {
    this.logger.log({
      level: 'error',
      message: `${message}:${trace}`,
    });
  }

  warn(message: string) {
    this.logger.log({
      level: 'warn',
      message: `WARNING: ${message}`,
    });
  }

  debug(message: string) {
    this.logger.log({
      level: 'debug',
      message: `${message}`,
    });
  }

  verbose(message: string) {
    this.logger.log({
      level: 'verbose',
      message: `${message}`,
    });
  }
}

NestjsのLoggerServiceとしては、log, error, warnのメソッドを最低限実装する必要がありますが、debug, verboseに関しては実装しなくても大丈夫です。
チームや、利用したい状況などを加味して決められればと思います。

SQLクエリもログとしてファイルに残したいね。TypeORMのLoggerを使ってみた

次です、SQLクエリをConsoleにもFileにものこしたいです。
今回はTypeOrmを使う前提でいきます。

TypeOrmModuleのモジュールインポートの部分でlogging: trueを渡してあげれば、一先ずコンソールにSQLがでます。

...省略...
@Module({
  imports: [
    TypeOrmModule.forRoot({
      ...省略...
      logging: true,
    }),
    LoggerModule,
  ],
...省略...

以下のような感じで出ます

query: SELECT users.id AS users_id, users.name AS users_name, users.email AS users_email FROM users users WHERE users.id = ? -- PARAMETERS: [1]

開発時であればこれで満足なときもありますが、本番だとファイルでも残っていると嬉しいこともありますよね

こちらも同じようにtypeormからLoggerインタフェースが提供されていますので、それを実装していきましょう

  logQueryError(
    error: string,
    query: string,
    parameters?: any[],
    queryRunner?: QueryRunner,
  ) {
    this.logger.error(this.queryRawer(query, parameters), error);
  }
...省略...

// RAW SQLを出力する
  private queryRawer(query: string, parameters?: any[]): string {
    if (!parameters) {
      return query;
    }
    const copyParams = Array.from(parameters);
    return query.replace(/\?/g, () => copyParams.shift() || '?');
  }

this.loggerは自分で実装したLoggerクラスです。Winstonを利用しているので、そのままファイルにも出力されます。

注意してほしいポイントとしては、logQueryErrorメソッドで渡されるquery文字列では、TypeORMのfindオプションのwhereなどで指定した動的なパラメタは?で表現されているため、実際に発行されたクエリでは無いということです。パラメタはparameters変数に格納されています。

私はRawなSQLが欲しかったためメソッドを一つ噛ませています。しかしここでも注意してほしいのが、parametersを破壊的に変更すると、実際のクエリ発行時にエラーが発生します。なのでArray.fromを使って配列を複製しています。
バグ的な挙動なため将来的には解消されるかもしれません。

後は、こちらのクラスのインスタンスをTypeOrmModuleのモジュールインポートの部分でloggerオプションに渡してあげればロギング完了です

余談：.where('users.name = "?"')のようなクエリを書くと死ぬ

上記のバグ的な挙動が気になってデバッグしたら、ほとんど場合で必ずエラーを吐くクエリを発見しました。

createQueryBuilder()
  .select('users')
  .from(User, 'users')
  .where('users.name = "?"')
  .orWhere('users.id = :id', { id: 1 })
  .getOne()

.where('users.name = "?"')の箇所を.where('users.name = :name', { name: '?' })と書けばエラーは発生しません。
TypeORMを使う場合は、SQLに直接?を書くことはしないようにしましょう。

他に

アクセスログとかも出したいですが、まだ未チャレンジです。
たぶん簡単にできると思います

以上