ゆで卵を食べるときは塩をかけるのと同じように、サーバを書くときはストラクチャードロギングをするのが当たり前といった状況になった昨今。世界のロガーたちはキー/バリュー形式の構造化データを出力すべく、その用途に特化したインターフェイスを獲得するに至っている。
一方、プログラミング言語やフレームワークによってはこの辺のサポートはけっこうまちまちで、人によってストラクチャードロギングに対しての理解度やロガーへの要求水準はけっこう違っているようである。
私がサーバを書く仕事を始めた頃なんかは、使っていたウェッブフレームワークはさも当然のように人間にとって読みやすく整形された文字列をログに吐いた。ほかにオプションはなかった。私は「ふーん。そんなもんかな」と思いながら、ログを上から下に読んでいたが、しかしこれは一件のログレコードが改行されまくっていたので、キーワードでgrepするだけで当然のようにぶっ壊れた。
今ではアプリケーションのログというもののありかたはけっこう変わっている。解析するツールやプラットフォームも進化したし、トレースだのメトリクスだのといったその他Telemetry的な情報と関連づけられた最も粒度が細かく信頼性の高いイベントデータ、それがログである、ということになっている。アプリケーションのロジックを知っていて欠損率も低いイベントデータとして、いろいろな用途の情報源としての潜在能力も高い。
むかし、隣の席にいた同僚が LTSVというフォーマットを発見し、「ヒューマンリーダブルかつマシンリーダブルなフォーマットでログを吐くのって、『良い』よね」みたいなことを控えめに言っていた記憶があるのだが、しかし私はその後、LTSVを本番で使うことはなかった。
つくるシステムが複雑化、または大規模化し、とんでもない量のログがアンデス山脈の雪崩の五倍くらいの勢いで流れてくるようになると、生ログが人間にとって読み易いかどうかはすぐにどうでもよくなってしまった。
デプロイされた環境のログはパースされ、値の意味を解釈され、フィルタされ、整形されたテーブル形式のUIを通して見る。だから生のログフォーマットへの要求は、人間にとっての読みやすさではなく、どの環境でも完璧に動くパーサがあり、仕様があり、ネストしたデータやコレクションなども表現できる高い表現力、などに移った。
そんなわけで、JSONが最高に素晴しいソリューションなのかについては若干の疑問があるけれど、様々なプラットフォームやロガーの状況を考えると、本番(というかデプロイされた環境)ではログはJSONで吐いとけばまあ間違いがない、というのが現代のログのフォーマット事情となっている。
(ちなみにOpenTelemetryはログをOpenTelemetry protocol (protobuf) で外側にいる collector/agent へpush形式で素朴に投げ飛ばす仕様を持っている。このプロトコルはgRPCなので、この場合のフォーマットはJSONではなくprotobufになる。ただ、アプリケーションと外側のログを直でOTLPでつなげてしまうと、 collector/agent やexport先にダウンタイムをつくるとログが欠損するリスクがあるので注意が必要。アプリケーション側とcolector/agent側にデプロイの依存関係ができてしまうので、ログを欠損させたくないなら(欠損させてよいアプリケーションが世の中にあるのかよくわからないが、)一旦ローカルマシン上のI/Oをある程度即座に行ってexportしておくという構成が妥当だと思う。OTLPに対応したOpenTelemetry Collector とかはデフォルトだと割とこの辺は素朴な構成だったりする。ちなみにOpenTelemetry の LogRecord 仕様とExpoter実装を使いつつも、export先をローカルファイル/標準出力へのI/O にすることは可能だ)
あとDocker Engineのlog driver経由で標準出力をfluentbit につなげたりする場合はJSONしか選択肢がなかったりする場合もやっぱりある)
さてここで、ストラクチャード某ロガーに特に関心のない人はこんな疑問を持つのではないだろうか。
「JSONのログ? そんなの、読めたもんじゃないのではないだろうか？」
そのとおりである。しかし今や、ストラクチャードロガーを名乗る多くのロガーは、人間に読み易いフォーマットと機械に読み易いフォーマットとを切り替える機能を持っている。本番ではJSONを吐くけれど手元のマシンで動かしているときは読みやすいフォーマットを吐く。なんなら色もつけときました、ぜんぶやっときました、といった具合である。
そういう意味で、現代では生データをヒューマンリーダブルかつマシンリーダブルにするのはロガーの仕事になってる。LTSVの仕事ではなく。
私はそこそこ色々な環境でサーバなんかをつくる仕事をしてきたと思うのだが、この分野でC#はけっこう進んでいる。
C#の標準のロガーの抽象レイヤーは、構造化データを出力することが想定されているし、ログの「スコープ」の概念も持っているし、OpenTelemetryのLogRecord仕様を使うこともできる。
ところで話は変わるけど、C#界にあるロガー実装のひとつ、[ZLogger](https://github.com/CySharp/ZLogger) をご存知だろうか。
ZLoggerは現時点では最も普及しているロガーというわけではないけれど、誰もが当たり前と思っていたログ呼び出し時のGCゴミの発生を劇的に抑制している高速なロガー実装である。
[ZLogger v2 による .NET 8活用事例 と Unity C# 11対応の紹介](https://neue.cc/2023/12/19_zlogger2.html)
普通に考えると、可変長パラメータをとるログ呼び出しのところはアロケーションが発生するとしか思えへんのだが、どのような工夫でそれを乗り越えているのか、といった点については是非上の記事などを見てほしい。
私が今日紹介したいのは、ZLogegr v2 のストラクチャードロガーとしてのAPIの進化についてである。
ZLogegr は バージョン2 でさらに汎用的に使えるロガーになったのだが、ログ呼び出しのAPIが現行世代のロガーにはないものに一新された。私はこれはなかなか良い感じだと思うのだが、ふと知り合いにこの辺の話をしてみたところ、「ふーん。そんなものかな」程度のそこそこの反応。そんなことよりアジャイルコンサルタントが書いた新刊がどうのこうの……みたいな話題が耳目を集めていることにきがつき、私はここにきてようやく、ストラクチャードロガーのAPIというのものがそこまで広く認知されていないことに思い至った。
そこで以下では、ただのロガーがストラクチャードロガー的な機能を獲得していく様を段階的に追いかけることで、改めてロガーのAPIについて考えていき、 ZLoggerの新しさを明らかにしてみたい。
## ストラクチャードロガー Lv 0 文字を入力にとる
ロガーを名乗るライブラリは大抵は以下のようなインターフェイスを持っていると思う。
```js
logger.info("冷えたビールで事態の収束を待つ")
```
ログレベルと出力したい文字列を指定するようになっているデザイン。
このへんがロガーとしては最低現の機能だろう。もちろん、用途によってはべつにこれで充分である。
通常は内部に タイムスタンプなどのメタ情報も保持していて、以下のようなかんじで整形した字を出してくれたりする。
```
[INFO] 2024-03-01 01:02:03 冷えたビールで事態の収束を待つ
```
与えた入力が文字列だけだったとしても、最終的な出力フォーマットを変更できるものもあるようだ。
```
{ level: "Information", message: "冷えたビールで事態の収束を待つ", timestamp: "2024-12-31 01:02:03" }
```
あ、なんだJSONにできんじゃん。しかしこれだけでは胸を張ってストラクチャードロガーを名乗ることはできない。
ちなみに、伝統的なロガーは出力先の設定がいろいろと豊富だったりするが、現代ではコンテナで動くサーバは標準出力にログを出しとけばいいじゃん、が解だったりするので、その辺の重要性は下がっていると思う。そのためここでは取り上げない。
## ストラクチャードロガー Lv1 キー/バリューを入力に取る
ログを構造化データとして扱うためには、なんらかの方法でロガーを経由して「構造化データ」を入力してあげなければいけない。
データといっても発生するログの文脈ごとに出力したいデータ型は様々なので、その都度動的に任意の型のキー/バリュー形式のデータをつっこめるようになっているとよい。
たとえば、なにか商品を閲覧したり購入したログに商品IDとかを出してたとする。このときのログが `"商品id 12345 を買ったよ"`のように文字列だとしたら、この「商品id」とかいう値はマシンリーダブルなデータであるとは言えない。JSONでいえば `"商品id": 12345` みたいなかんじで、値の部分と、それが何のデータなのかを機械的に解析できるようになっていてほしい。
たとえば golang の zerolog などは以下のような身も蓋もないインターフェイスを持っているようだ。
```go
log.Debug().
Str("Scale", "833 cents").
Float64("ID", 12345).
Msg("Fibonacci is everywhere")
log.Debug().
Str("Name", "Tom").
Send()
```
素朴にキー/バリューを指定するだけ。もはや文字列メッセージはあってもなくてもどっちでもよい存在になっている。
rust の slog なんかは、以下のようなマクロが用意されている。
```rust
info!(logger, "Hello", "name" => "Bob");
```
最初の引数は文字列メッセージ。以降はキーバリューを任意にいくつでも指定できる。
これが関数ではなくマクロである理由については以降でもう一度取り上げてみようと思う。
おもしろいのは C# の一般的なロガーのインターフェイスである。
[slog](https://serilog.net/) の公式サイトに載っている例はこう。
```cs
log.Information("User {username} logged in from {ip_address}", "Bob", "127.0.0.1")
```
パッと見、文字列テンプレートに変数を埋め込んでいるように見える。
しかし実はこれは、以下の3つの入力を同時にロガーへ与えている。
1. "User Bob logged in from 127.0.0.1" というテキストメッセージ
2. キーが`"username"` 、バリューが `"Bob"` のデータ
3. キーが`"ip_address"` 、バリューが `"127.0.0.1"` のデータ
キー/バリューを指定するという目的を果たしつつ、旧来のロガーと同様のノリで人間向けにレンダリングされたメッセージも提供してくれるという、アイデアが光るAPIなのである。
ロギングは、本筋の本来書きたいプログラムではなくただの添え物、人間向けのメモみたいなもんなので、ソースコード上では主張が強くなくかつログの意図がパット見でわかる見た目をしているとよい。その観点でいくとこのインターフェイスは優れている。
C# では標準的なロガーの抽象レイヤーである [Microsoft.Extensions.Logging](https://learn.microsoft.com/ja-jp/dotnet/core/extensions/logging?tabs=command-line) も同様のコンセプトを採用しているので、現状はこれが一般的のようである。
## ストラクチャードロガー Lv2. 複数フォーマットへの出力
入力にとったキー/バリュー形式のデータはそれ自体は特定のフォーマットに依存していない。上で紹介したロガーはすべて、様々なフォーマットで出力することがでできる。
上で書いたserilog の例を続けるなら、
```cs
var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;
log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);
```
このようにログ出力を書いたソースコードがあったとして、
ローカルの開発環境では↓のように人間が読めるフォーマットをすることもできるし、
```
09:14:22 [Information] Processed { Latitude: 25, Longitude: 134 } in 034 ms.
```
本番では↓のようにJSONに切り替えることができる。
```json
{"Position": {"Latitude": 25, "Longitude": 134}, "Elapsed": 34}
```
世の中のストラクチャードロガーを名乗るライブラリは大抵はこの辺の機能までは搭載している。ここまでくればストラクチャードロガーを名乗ってももんくはつかない。柔道でいえば地区予選通過である。
テキストメッセージではなく構造化データを自由に入力にとれるようになったが、そうなってくると実用のためにはさらに欲しい機能がでてくる。
## ストラクチャードロガー Lv3. スコープの概念
ここで一旦、ログのことは忘れ、RDB のテーブルのことを考えてみてほしい。
これを読んでいる人は、 ユーザのデータが入ったテーブルをつくったことは一回や二回ではないと思う。
仮に、その usersテーブルに入っている1000億件のレコードの中に、nameがBob、idが3 のレコードがあったとする。
このDBにはuserに関連するテーブルがいっぱいあるはずだ。ゲームならユーザが獲得したアイテムを保存するテーブルもあるだろうし、blogみたいなシステムなら post を保存すテーブルだってあるかもしれない。
それらすべてのテーブルについて、ボブに関連するレコードには漏れなく、ただ一件の漏れもなく、 `user_id=3` が書き込まれているはずだ。もしも、ボブのpost なのに user_id のカラムに3 が書き込まれていなかったら? その意味することはなにか。この世の終わり。あるいはそのdbは壊れている。`user_id = 3` のクエリをしてもボブをみつけることはできず、ボブはまるで映画サイコに出てきた底無し沼に車ごと沈められてしまった人のように、二度とは会えないのである。
今言ったことは全て忘れ、もう一度ログの話題に戻ってきてほしい。
典型的には、ログには trace_id、span_id、リクエストidなどの、いくつかのログのまとまりすべてに漏れなく入っているべきキーが大抵はある。
我々がボブの操作をログに記録している場合、 `user_id=3` のキー/バリューが入ってないログがあるのだとしたら、user_id=3 でのログ検索は役に立たない。ログでもDBでも同じ。データとして扱いたいなら、そのデータについているはずの外部キーは、「たまについてることがある」ではカンペキにマシンリーダブルだとは言えない。人間の目視に頼ることになってしまう。
ストラクチャードロガーを名乗るロガーの多くはこういった問題に対処する能力を持っている。うんうん。
たとえば C# の Microsfot.Extensions.Logging は、using文で括ったブロック内のすべてのログ呼び出しに特定のキー/バリューを付与する機能があります。
以下は公式サイトで紹介されている例。(少し改変)
```cs
using (logger.BeginScope("{transactionId}", transactionId))
{
logger.LogInformation("Reading value for {id}", id);
var result = await repository.GetAsync(id);
if (result is null)
{
logger.LogWarning("Not found {id}", id);
}
}
```
この例では、先頭のusing 文 でログのスコープを開始している。このブロックの内側の「Reading value for...」のログにも transactionId がつくし、「not found」 のログにも transactionId がつく。
```json
{ "level": "Information", "message": "Reading value for 3", id: 3, transactionId; 98765 }
{ "level": "Warning", "message": "Not found 3", id: 3, transactionId; 98765 }
```
C# の using 文は await を跨いで括ることができるため、webフレームワークもこの機能をmiddlewareで利用していて、request_id のようなものをある程度自動でつけてくれます。Opentelemetrly の SDK を使っていれば trace_idやspan_id も自動でつきます。
さらに言うと、アプリケーションを書いているプログラマが自前でスコープを宣言することも想定されていて、user_idのように、そのアプリケーション固有のスコープを自由に宣言できることは実際とても有用です。
「スコープ」のほか、同様の目的のためにロガーに階層構造を持たせているロガーも存在します。
たとえば先に紹介した rust の slogは、あるロガーの設定を踏襲しつつ、デフォルトで付与されるキー/バリューを追加したロガーインスタンスを新規作成することができるようになってます。
```rust
let logger = logger.new(o!("user_id" => 3))
```
この例では、新しくインスタンス化したロガーを使う限り、必ず user_id=3 がログに書き込まれることが保証されるというわけです。
## ストラクチャードロガー Lv4 コンパイル時解析
ここまでストラクチャードロガーのいくつかの機能をおさらいしてみたが、トラディショナルなロガーに比べて随分と実装が複雑そうである。
特に、可変長引数としてキー/バリューを度せるところなんかは、素朴に考えるとボクシングや動的なバッファ確保が避けられなそうだ。素朴に文字列をぶち込むだけのロガーに比べるととても遅そうである。
それに、アプリケーションのログの有用性が高まってくると、ログを出す頻度や一件あたりのデータ量も増えがち。
CPUバウンドな処理のパフォーマンスにそれなりに気を遣っているフレームワークを使っていたとしても、我々がその上で遅いロガー呼び出しを連打、連打、連打、したら、新たなボトルネックを誕生させてしまいかねない。
ここで注目してみたいのは Rust のロガーである。
```rust
let logger = logger.new(o!("user_id" => 3)),
```
Rustの場合、こういう可変長パラメータをとるものはすべからくマクロになっている。(マクロというのはコンパイル時にソースコードからRustソースコードを展開する機能のこと)
マクロである理由のひとつは、可変長引数パラメータを実行時ではなくコンパイル時に展開することで、実行時のオーバヘッドを減らすためだ。
Rust では標準出力に字を出す `print!` もマクロになっている。
```rust
print!("Hello {}!\n", name);
```
たとえばこれは以下のように展開され、
```rust
std::io::_print(
// Simplified expansion of format_args!():
std::fmt::Arguments {
template: &[Str("Hello, "), Arg(0), Str("!\n")],
arguments: &[&name as &dyn Display],
}
);
```
実行時にはサイズ固定の配列の処理にまでは単純化されるようである。 (https://blog.m-ou.se/format-args より)
多くの言語がログ呼び出しの可変長パラメータを実行時に解釈するのに対して、コンパイル時にこれを解釈する方式がとれるとパフォーマンスの面では大きめのアドバンテージがある。
このようなコンパイル時最適化機能を持っている言語はRustのほかにもある。C# もそのひとつ。
現在のC# は、Roslynコンパイラのパイプライに割り込んで C#ソースコードから動的にC#ソースコードを展開する機能を持っているが、これは目的としては上記のようなマクロとほぼ一緒といっても過言ではない。
たとえば、Unity の [Logging](https://docs.unity3d.com/Packages/
[email protected]/manual/index.html) パッケージは、まさにロガーのメソッドをSource Generator で自動生成することで、コンパイル時に可変長パラメータを解釈している。
ただこれはUnity専用だし、Microsoft.Extensions.Logging の Abstarctionを完全に無視しているので、サーバサイドとかで広く使えるものではない。
汎用的なロガーのなかで同様の最適化がかかるロガーのひとつが ZLogger の v2である。
先に紹介した [ZLogger v2 による .NET 8活用事例 と Unity C# 11対応の紹介](https://neue.cc/2023/12/19_zlogger2.html ) に詳しいのだけれど、ZLogger は [Custom String Interpolation Handler](https://learn.microsoft.com/en-us/dotnet/csharp/whats-new/tutorials/interpolated-string-handler) というコンパイラの機能を利用して、コンパイル時にログのパラメータを解析する。
以下がZLogger のログ呼び出しのAPIだ。
```cs
logger.ZLogInformation(