概要

www.npmjs.com

主にexpressなどのサーバー上で動作することを期待した、構造化ロギングライブラリを作成した。この記事は、その辺の概要を覚書程度に記すものである。

背景

AWSのCloud WatchやGCPのCloud Loggingといった環境の中で、Nodejsサーバーからログを書き出す方法論の一つとして構造化ロギングがある。

Nodejsが標準で搭載する console.log は柔軟にログを書き出せるが、前述する環境だと単なるテキストと扱ったり、複雑なデータ構造のデバッグに向かない。そのため、JSON.stringifyや%jを用いてデータなどをJSONに変換したり、severityをその中に埋め込んだりと様々な工夫がある。

一方で、console.logは直ちにstdoutやstderrに書き出してしまうため、一つのリクエストの中であっても同時にリクエストが走った場合、ログの関係性が追いづらくなってしまう。

こんな感じで入り乱れるよね

request1 aaa
request2 aaa
request1 bbb
request1 ccc
request2 bbb

そこで、コンテクスト（例えば、リクエスト単位など）毎にログを集約・構造化することでログの関係性・前後関係を追いやすくすることが求められる。

こんな感じでまとめるイメージ。

{ context: request1, lines: [aaa, bbb, ccc] }
{ context: request2, lines: [aaa, bbb] }

今回、お仕事の中で紹介してもらった logone-go を参考にNodejs向きに実装した。大本がGoであり、Nodejsの事情や利用シーンの想定から大幅に手を加えているが、大変参考になったのでここで作成者の hixi-hyi に感謝を示したい。

アーキテクチャ

今回の用途ではexpressから利用することを想定している。 −−が、その一方で、お仕事ではRemixを利用していたり、クライアントサイドから利用される可能性も考慮したかった。

なので、選択的にどこにログを出力するか、どこから利用できるかという観点と構造化ログを作成する核心の機能を別のパッケージで提供したかった。

multi-package architecture

現在提供しているライブラリは以下の3つある

www.npmjs.com

@logone/core

ログを集約し、構造化するコア。 adapterを注入することで、出力先を選択できる

@logone/adapter-node

nodejs上で動作するアダプタ。 stdout, stderrにログを書き出す。

他の環境やファイル出力など、このadapterを実装・交換することで可能になる。

※同期性や複数出力先などは考慮が足りてない... 今後の課題

@logone/express

express上でlogoneを開始・出力するためのライブラリ。リクエストを受け付けたらログの収集を開始し、レスポンスが発行されたらログを出力する。

現在はadapterを内包しているが外から注入できたほうがいいかもなーと思っている。

monorepo

これらのパッケージの運用・リリースを行うのにmonorepoの構成を採用している。そのため、開発リポジトリは以下の一つのみ。

github.com

monorepoの運用については以下の記事を書いた際に検証し、得た知見をそのまま利用している。

mizuki-r.hatenablog.com

Usage

以下のような実装を考える。

import { createLogone } from '@logone/core'
import { createAdapter } from '@logone/adapter-node'

const logone = createLogone(createAdapter())
const main = () => {
  const { logger, finish } = logone.start('example')

  logger.info('hello world')

  finish()
}

これを実行すると、このようなログを1行にまとめて出力する。

{
    "type": "example",
    "config": {
        "elapsedUnit": "1ms"
    },
    "context": {},
    "runtime": {
        "severity": "INFO",
        "startTime": "2024-05-01T01:02:03.456Z",
        "endTime": "2024-05-01T01:02:04.456Z",
        "elapsed": 1000,
        "lines": [
            {
                "severity": "INFO",
                "message": "hello world",
                "payload": [],
                "fileLine": 8,
                "fileName": "/path/to/example.ts",
                "time": "2024-05-01T01:02:03.456Z"
            }
        ]
    }
}

finish関数が実行されるまでログはlogoneに収集され、出力されない。 finish関数が実行されて初めてログはadapterを経由して出力される。

ここから、logoneにおける要素と想定ケースを説明していく。

context

ログの集約単位を示す情報をcontextには設定できる。例えば、リクエストなんかでは以下のように使うことができる。

const { logger, finish } = logone.start('request', {
  url: req.url,
  method: req.method,
  host: req.headers.host,
  userAgent: req.headers['user-agent'],
})

この設定によって、そのログがどのリクエスト（などのコンテクスト）で実行されたかの関係性が自明になる。

runtime elapsed

ログの開始から終了までの経過時間を1ms単位で出力する。 configで渡すInterfaceにはしているが今のところ1ms固定なので注意。

runtime severity

Severityは以下のものを用意している。 - DEBUG - INFO - WRNING - ERROR - CRITICAL

各Lineで出力されたSeverityのなかでプライオリティが一番高いものをruntimeのSeverityとして指定している。プライオリティは上のリストで下に行くほど高い。

今後の展望としてSeverityの脚切りができるようにはしたい。

file information

今回工夫したものとしては、このファイル情報の出力である。なぜならば、JavaScriptは関数の呼び出し元という情報を原則保持しないためである。（実行環境によって差異がある、Nodeはサポートしていない）

ただ唯一の例外がErrorオブジェクトによるStack Traceである。今回はErrorオブジェクトを発行して、呼び出した関数のStackTraceからファイル情報を抜き出している。

  private getCallerPosition(): [string | null, number | null, number | null] {
    const stack = new Error().stack
    const rows = stack ? stack.split(/\n/) : []
    const current = rows[4]
    if (!current) {
      return [null, null, null]
    }
    const [file, lines, chars] = current.replace(/\s*at\s+/, '').split(/:/)
    return [
      file ?? null,
      lines ? Number(lines) : null,
      chars ? Number(chars) : null
    ]
  }

github.com

雑に引っこ抜いているので、フォーマット崩れはあるかも... とはいえ、これによって（生成後のJSファイルではあるが...）実行場所を把握しやすくなっている。

まとめ

−−というわけで、logone-goの移植、@logone/coreを作成しました！ adapterを追加すればあちこちで使えるんじゃないかな〜というのと、多分NodeJSだけで動くようには作ってないと思うのと、動作についてはzero-dependencyなので非常にライトに使えると思っています。

NodeJS界隈の構造化ログだと、child-processなどで集約していたり、かなり工夫して頑張っているライブラリも多いですが、logoneは汎用性に重きを置いている（それが本当に必要なのかはわからない）ため、非常にライトな実装と動作になっています。気軽に試してみたい方はぜひ触ってみてください。

のらねこの気まま暮らし

技術系だけど、Qiita向きではないポエムとかを書くめったに更新されないヤツ

nodejsで利用する構造化ロギングライブラリ、logoneを作成した

概要

背景