🥴

Web開発における使いやすいログ入門

2022/04/20に公開

こんなログを書いている人が対象です。

{
    "message": "HogeController.index(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeService.findListById(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeRepository.findListById(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeRepository.findListById(). found Hoge!",
    "level": "info"
}
{
    "message": "HogeService.findListById(). found Hoge!",
    "level": "info"
}
{
    "message": "HogeController.index(). found Hoge!",
    "level": "info"
}

ちなみに文中でinfoログはアクションごとに書くと書いてますが、フレームワークなどのセットアップやティアダウン処理は別です。あくまでアプリ内部のフローの話です。

悪い例から

まずは、僕のかつてのログをみてください。ちなみに、アプリのアーキテクチャは Conroller - Service - Repository(DBアクセスレイヤ) の関係になっています。RailsやLaravelなどのユーザーはRepositoryをActiveRecordやEloquentと読み替えてください。

サンプルコードはTypeSciptで書かれています。特定のフレームワークを使った実際のコードではなく、イメージで書いているので注意してください。

まずはControllerです。処理が始まる前と終わったあとにそれぞれinfoレベルのログを書いていました。なぜ処理の前後にinfoログを書いていたのかというと、バグがあったときにどの処理まで進んだのか知りたかったからです。

エラーがあればerrorレベルのログを書いて、フレームワークのエラーハンドラーにまた渡していました。実は、フレームワークのエラーハンドラーもエラーを受け取ったらそのままエラーログを書いてくれる仕組みでした。なぜ、わざわざもう一度自分でエラーログを書いていたのかというと、どのコントローラーで起きたエラーなのかメタ情報が知りたかったためでした。

HogeControllerr

class HogeController {
  async index(request) {
    // 処理が始まる前にログ。
    logger.info('HogeController.index call!');
    
    // TypeScriptの書き方ではないがイメージ。例外があればcatch。
    try {
      const hoges = await HogeService.getAllHoge(request.user);
      
      // 処理が終わったらログ。
      logger.info('HogeController.index called!');
      return hoges;
      
    // geAtAllHogeがエラーを投げたら
    } catch (error) {
      // どのコントローラーかエラーログ書いてた。
      // userIdつけてるときもあれば、つけてないときもあった。
      logger.error(`Error in HogeContoller.index(). userId: ${request.userId}, error: ${error}`);
      
      // もう一度エラー投げて、フレームワークにエラーをハンドリングしてもらう。expressとかだったら next(error)。
      throw error;
    }
  }
}

次にServiceです。こちらもControllerと同じように処理の前後にログ書いてました。なんなら、コピペの過程でログの内容が正しくないものになっていたものもありました。

HogeService

class HogeService {
  async getAllHoge(requestUser){
    // 処理が始まるよというログ。
    logger.info('HogeService.getAllHoge. finding hoge... ');
    
    // なんかの条件チェック失敗したら例外投げる。
    if(!requestUser.canGetHoge()){
      // 一応エラー発生した場所もエラーログ書いておく。
      logger.error('requestUser.canGetHoge() 権限エラー')
      throw new Error('権限エラー');
    }
    
    const models = await HogeRepository.findAllHoges();
     
    // 処理が成功したよというログ。 
    // 修正の過程でメソッド名が変わったのにログの内容は修正忘れてる。
    logger.info('HogeService.getHoges found hoge!');
    
    return models;
  }
}

次にRepositoryと続こうと思ったのですが、同じことの繰り返しなので省略します。同じように処理の前後でinfoレベルのログ書いて、エラーがあったらその場でerrorレベルのログを書きつつエラーを投げるの繰り返しです。

またログサービスにはinfoレベル以上のログのみ記録していました。

ある日自分のログが使いにくいということに気づく

ある日、お客さんからある機能うまく利用できないと言われました。お客さんのidをもとに該当のログみてみようとおもいログサービスを覗いてみると、

{
    "message": "HogeController.findListById(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeService.findListById(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeRepository.findListById(). finding hoge...",
    "level": "info"
}
{
    "message": "HogeRepository.findListById(). found Hoge!",
    "level": "info"
}
{
    "message": "HogeService.findListById(). found Hoge!",
    "level": "info"
}
{
    "message": "HogeRepository.findListById(). found Hoge!",
    "level": "info"
}
{
    "message": "HogeController.index(). found Hoge!",
    "level": "info"
}
...中略...
{
    "message": "HogeRepository.create(). found Hoge!",
    "level": "info"
}
{
    "message": "接続エラー",
    "level": "error"
}
{
    "message": "Error in HogeController.index(). userId: 1,  error: DBエラー",
    "level": "error"
}
{
    "message": "ここにスタックトレース",
    "level": "error"
}

なんじゃこりゃ！？

やたら多い取得系のログと、誰がやったのかわからないinfo系のログと、埋もれるエラーログがありました。データの9割がゴミでした。あとどうやってuserId検索できるんだっけ？

なぜ使えないログを生み出してしまったのか。理由をまとめました。

infoログだとおもっていたものはdebugログレベル。
ControllerやServiceといったレイヤーごとに記録をしない。アクションごとにinfoログで記録する。
errorログはエラーごとに１つ。原因調査しやすくメタ情報を付与する。
ユーザーが直前までどのような行動をとっていたのか検索できるように、ログにuserIdを必ずつける。
messageのなかにメタ情報を埋め込まない。検索できるようにちゃんとjsonのキーとバリューとして記録する。

反省を踏まえて

まずロガーをカスタマイズしました。第2引数にはいるobjectはそのままjsonとして扱えるようにしました。

ロガーのカスタマイズ

logger.info('message here', {
  userId: 1,
  requestId: 'gjeaijgeiajke'
})

出力

{
  "level": "info",
  "message": "message here",
  "userId": 1,
  "requestId": "gjeaijgeiajke"
}

次にControllerの変更します。すべてのinfoログをdebugに変更し、エラーはフレームワークのエラーハンドラーのログに任せるようにしました。しかし、エラーをそのまま記録しても役に立たないのでメタ情報を付与します。ここに関しては後で触れます。

HogeControllerr

class HogeController {
  async index(request) {
    // 処理が始まる前にログ。
    logger.debug('HogeController.index call!');
    
    // TypeScriptの書き方ではないがイメージ。例外があればcatch。
    try {
      const hoges = await HogeService.getAllHoge(request.user);
      
      // 処理が終わったらログ。
      logger.debug('HogeController.index called!');
      return hoges;
      
    // geAtAllHogeがエラーを投げたら
    } catch (error) {
　　　 // もう一度投げるならtry-catchで囲む必要ないけど、構造を前セクションと合わせたかった。ログはフレームワークのエラーハンドラーに任せる。
      throw error;
    }
  }
}

次にServiceを書き換えます。こちらもinfoをすべてdebugに書き換えました。また、エラーなげるときに無駄にログを書かないようにしました。エラーは直接エラークラスを使わずに、フレームワークが提供するクラスを利用するようにも修正しています。

HogeService

class HogeService {
  async getAllHoge(requestUser){
    logger.debug('HogeService.getAllHoge. finding hoge... ');
    
    // なんかの条件チェック失敗したら例外投げる。
    if(!requestUser.canGetHoge()){
      throw ForbiddenError('権限がありません。');
    }
    
    const models = await HogeRepository.findAllHoges();
    
    // アクションしたらinfoログをつける。
    logger.info('activity log', {
      userId: 1,
      eventType: 'view.hoge',
      timestamp: new Date().toISOString(),
    })
     
    logger.debug('HogeService.getHoges found hoge!'); 
    return models;
  }
}

最後に、エラーハンドラーの修正です。僕が利用しているフレームワークでは、フレームワーク全体のラーをキャッチするエラーハンドラーは、ミドルウェアとして実装されており、エラー内容がカスタマイズ可能になっていました。そこで、エラーの内容につぎの内容を付与しました。

リクエストURL
HTTPメソッド
リクエストボディ
リクエストクエリ
リクエストパラメータ(URLの一部)
リクエストヘッダ
リクエストユーザーのid
レスポンスステータスコード
タイムスタンプ

エラーハンドラーのカスタマイズイメージ

export class LoggingExceptionFilter extends BaseExceptionFilter {
  catch(exception: Error, request) {
    this.logger.error(exception.message, {
      path: request.url,
      requestMethod: request.method,
      requestBody: request.body,
      requestQuery: request.query,
      requestParam: request.params,
      requestHeaders: request.headers,
      userId: (request.user as UserEntity | undefined)?.id ?? null,
      responseStatus: httpStatus,
      timestamp: new Date().toISOString(),
    });
  }
}

生まれ変わったログ

{
    "message": "activity log",
    "level": "info",
    "userId": 1,
    "timestamp": "2022-04-20 10:10:10",
    "eventType": "view.hoge"
}
{
    "message": "activity log",
    "level": "info",
    "userId": 2,
    "timestamp": "2022-04-21 10:10:10",
    "eventType": "create.hoge"
}
{
    "message": "DB接続エラー",
    "level": "error",
    "userId": 2,
    "timestamp": "2022-04-22 10:10:10",
    "path": "https://example.com/hoge",
    "requestMethod": "PUT",
    "requestBody": {
      "comment": "hogeよりfugaがいいと思う"
    },
    "requestQuery": "",
    "requestParam": "",
    "requestHeaders": {
      ...省略
    },
    "responseStatus": 500
}

JSON形式だと、CloudWatchであれば { $.userId = 1 } のように検索すれば、フィルターしてそのユーザーのログだけ出してくれます。

ステータスコードの内容から大体のエラーの位置が把握でき、エラーのメッセージからエラー箇所が特定できます。またリクエストbodyなどを記録することでどのような状況だったのかが理解できます。

eventTypeというのはログフィルター機能などでなにかのメトリクスを計測したいときように念の為つけてます。

ただし、ビジネスメトリクスをCloudWatchのような監視ツールで計測するのは向いていないことがわかったため、現在はあまり利用できてません。

めっちゃ使いやすい ₍₍ (ง ˙ω˙)ว ⁾⁾

おまけ

途中ちらっとコードに書いてありましたが、フロントからリクエストごとにトレースidを付与しておくと、もし一つのリクエストに複数のログを出したり、のちのちイベント駆動とかでトレースidが必要になったときや、ビックデータ分析のときにトレースidが必要になったときなど、何かと役に立ちます。

フロントでリクエストするときリクエストidをつける。

axios.get('/example.com', {
  headers: {'X-REQUEST-ID': nanoId()}
});

バックエンド側で、保持しておき、ログに追記したり。(CORSで許可するのを忘れずに)

さいごに

個人的にほそぼそともくもく会やってます。すこしずつ大きくしていこかなと思ってます。ゆるぼです~

https://side-projects.studio.site/