構造化ログのタイムスタンプ形式

みんなtai64nを使おう。と言いたいところだけれど、サポートしてるところが見当たらないのでナシだ。

個人的に好きなのはナノ秒単位のUnixタイムスタンプだ。 OpenTelemetryのOTLPでもナノ秒タイムスタンプを使っている。

  "logRecords": [
    {
      "timeUnixNano": "1544712660300000000",

(opentelemetry-protoのexample より)

しかし、これはスキーマが厳密に定義されているOTLPだからこそできる事であって、普通にJSON linesのログをあちこちで扱うには問題がある。

  • レコード名が "time" や "timestamp" だとナノ秒なのかマイクロ秒なのかわかりにくい
  • そもそも人間はUnixタイムスタンプを読めるようにできていない

整数の代わりに実数を使えば、精度はマイクロ秒に落ちてしまうものの、単位が秒だと自然に判断できるので前者の問題は解決できそうに思える。しかし、DataDogの場合はUnix epochからのミリ秒をタイムスタンプとして採用しているので、カスタマイズが必要になる。

https://docs.datadoghq.com/logs/log_configuration/pipelines/?tab=date#date-attribute

BigQueryの場合はフィールドをタイムスタンプ型だと指定すると秒単位の実数として扱うようだ。Unixミリ秒のサポートは見つからない。

Loading JSON data from Cloud Storage  |  BigQuery  |  Google Cloud

UnixタイムスタンプもあきらめてISO8601を使えば、サービスによる精度の解釈違いも起きないし、JSONを直接人間が読む時も読みやすくなる。日付と時間の区切りはTよりもスペースの方が読みやすいので "YYYY-MM-DD hh:mm:ss.ssssssZ" 形式にしても良いだろう。

ログ管理ツールは運用メンバーのタイムゾーンが多様である前提で作られていることが多いのでUIから表示するタイムゾーンを選べるし、BigQueryでも "+0900" をつけていてもUTCに変換して取り込まれるそうだ。それでも運用チームが日本ローカルでメンバーがJSONをそのまま読む機会が多いなら、ローカルタイムを使って末尾に"+0900"をつけるのでもいいだろう。

dev.classmethod.jp

構造化ログのフォーマット logfmt vs JSON lines

構造化ログのプラクティスをあちこちで調べていたら、logfmtを推奨する記事を見つけたので調べてみました。

先に結論を言うと、JSON linesを使っておくのが良さそうです。

logfmt について

logfmtとはスペース区切りで key=value を並べたフォーマットです。文字列にはクォートとエスケープによってスペースや改行を含められます。

at=info method=GET path=/ host=mutelight.org fwd="124.133.52.161"
  dyno=web.2 connect=4ms service=8ms status=200 bytes=1653

(logfmt から引用)

あちこちで logfmt のリファレンスとして紹介されているのはこの記事です。

https://brandur.org/logfmt

発明されたのはどこか分かりませんが、流行り始めたのはHerokuの標準フォーマットとして使われていたからのようです。

アプリケーションのログ記録のためのベストプラクティスを記述する | Heroku Dev Center

JSONに比べて目に優しいのがメリットです。とくに key がクォートされていないのが良いですね。

ログ集約サービスのlogfmt対応状況

個人的に興味があって調べた範囲です。有名なサービスを網羅しているわけではありません。

ということで、JSONに比べると十分に標準化されているとは言えず、とはいえlogfmtに対応していないサービスには変換して送れば使える状態です。

logfmtの問題点 -- 信頼できる仕様がない

信頼できるところがフォーマットの明確な仕様を決めていません。

例えばあちこちでlogfmtの一次ソースのように紹介されている https://brandur.org/logfmt では次のように書いてある部分があります。

Splunk also recommends the same format under their best practices so we can be sure that it can be used to search and analyze all our logs in the long term.

で、リンク先を見てみると、Splunkが推奨している key-value 記法にはなんとカンマ区切りがついています。この記事の著者が単にカンマを見逃したのか、そもそもlogfmtを厳密な仕様をもったフォーマットとして考えていないのかは分かりません。

key1=value1, key2=value2, key3=value3 . . .

(https://dev.splunk.com/enterprise/docs/developapps/addsupport/logging/loggingbestpractices/ より)

フォーマットが決まっていないことで弊害もあります。 Python の構造化ロギングライブラリとして有名なstructlogですが、未リリースのバグ修正としてlogfmtエスケープ漏れがあります。現時点の最新版である24.1.0ではエスケープが不足していると言うことです。

structlog/CHANGELOG.md at 555c3878a98e5b95986ca5cc36959d4eeaff8397 · hynek/structlog · GitHub

このバグ修正で、structlogの作者がlogfmtの仕様がどこにあるのか質問して回答されたのはGoのライブラリに含まれるEBNFです。

LogfmtRenderer has a bug with escaped double quotes · Issue #511 · hynek/structlog · GitHub

logfmt package - github.com/kr/logfmt - Go Packages

しかし、このGoのライブラリがリファレンス実装でGrafana等で使われていると言っていますが、実際にGrafanaで使われているライブラリはこちらでした。

https://github.com/go-logfmt/logfmt

このライブラリのREADMEでは、logfmtのリファレンスとしては冒頭の https://brandur.org/logfmt を紹介した上で、仕様が標準化されていないと述べた上で、 https://github.com/kr/logfmt を一番信頼できる仕様だと述べています。

ということで、一応 https://github.com/kr/logfmt が定義している仕様が一番信頼できそうではあるけれども、ほとんどの場所でlogfmtのリファレンスは https://brandur.org/logfmt になっているために、各実装が https://github.com/kr/logfmt に準拠しているかは確認してみないと分かりません。

たとえば、 key=value ではなく flag という記法を flag=true と同じ意味として扱うケースがありますし、そもそもboolが true/false なのか True/False なのかといったことも決まっていません。

まとめ

logfmtには信頼できる仕様がないため、あちこちのシリアライザとパーサーに互換性があるか信頼できません。

また、BigQuery や CloudWatch logsといった大手のサービスでプレインテキスト扱いになります。

他にもJSONに比べるとネストができない、配列の書き方が決まっていないなどの問題があります。

Herokuを使う場合や、コンソールやテキストファイルのログがメインの場合はlogfmtでもいいかもしれませんが、最初から構造化ログを外部サービスに送る前提で使う場合は、最初からJSONを使っておいた方が良いと思います。

Goのライブラリに対する再現コードを置く場所

golang

Goのライブラリのメンテナをしていると、再現コード付きのIssue報告をもらうことがあります。

さて、そのサンプルコードをどうやって動かせばいいでしょうか？ディレクトリを作って go mod init して、、、というのは面倒ですよね。 ライブラリのコードにデバッグ用のトレースを入れたり、バグ修正コードで再現しなくなることを確認する方法も考えないといけません。

その場合、そのライブラリの中に _issue みたいなディレクトリを作って、その中に issue1234.go のようなファイルを作るのが楽です。 go build issue1234.go のようにすると、ちゃんと親ディレクトリのmodを使ってくれるので、ローカルの修正が可能です。

再現コードに外部依存が入っている場合は、仕方ないので go mod init が必要です。その場合も再現コードを置くディレクトリはライブラリのディレクトリのサブディレクトリにするか、隣のディレクトリにすると、 replace を使ってライブラリのリポジトリのコードを使うのが楽になります。

Ryeを使っていると uv venv が動かない

python

Ryeを使っている状態で uv venv をすると、次のようなエラーになります。

$ uv venv
  × Querying Python at `/Users/inada-n/.rye/shims/rye` failed with status exit status: 2:
  │ --- stdout:

  │ --- stderr:
  │ error: unexpected argument found
  │ ---

python や python3 コマンドが rye コマンドのシンボリックリンクになっていて、ryeはpythonとして起動された場合は .python-version などのルールに従って決めたバージョンのPythonを起動するようになっています。ちなみに +3.8 みたいにしてバージョンを指定することもできます。

$ python3 +3.8 -msite
sys.path = [
    '/Users/inada-n/tmp',
    '/Users/inada-n/.rye/py/cpython@3.8.18/install/lib/python38.zip',
    '/Users/inada-n/.rye/py/cpython@3.8.18/install/lib/python3.8',
    '/Users/inada-n/.rye/py/cpython@3.8.18/install/lib/python3.8/lib-dynload',
    '/Users/inada-n/.rye/py/cpython@3.8.18/install/lib/python3.8/site-packages',
]
USER_BASE: '/Users/inada-n/.local' (exists)
USER_SITE: '/Users/inada-n/.local/lib/python3.8/site-packages' (doesn't exist)
ENABLE_USER_SITE: True

しかし、 uv venv はデフォルトのPythonを利用するときに python3 コマンドを PATH から見つけた後、シンボリックリンクを解決してから実行してしまいます。python3のシンボリックリンクを解決するとryeになるので、ryeをryeとして起動してしまい、pythonを実行することができません。

UV venv doesn't work on MacOS when Rye is installed · Issue #1791 · astral-sh/uv · GitHub

将来的には解決されるでしょうが、とりあえずの回避策を紹介しておきます。 rye は自身のテストを実行するときに複数バージョンのPythonをあるディレクトリ以下にダウンロードして使っていて、そのディレクトリを UV_TEST_PYTHON_PATH という環境変数で指定しています。

これを利用して、 $HOME/pythons というディレクトリに rye が持っているPythonのpython3.xコマンドへのシンボリックリンクを集めて、UV_TEST_PYTHON_PATHにそのディレクトリを設定してやります。そしてデフォルトで使いたいバージョンに python3 というシンボリックリンクも作っておきます。

$ mkdir pythons
$ cd pythons
$ for i in ~/.rye/py/*/install/bin/python3.*; do ln -s $i; done
$ ln -s python3.12 python3
$ ln -s python3.12 python
$ cd

$ export UV_TEST_PYTHON_PATH=$HOME/pythons

$ uv venv hoge
Using Python 3.12.1 interpreter at /Users/inada-n/.rye/py/cpython@3.12.1/install/bin/python3.12
Creating virtualenv at: hoge

$ uv venv -p3.8 hoge
Using Python 3.8.18 interpreter at /Users/inada-n/pythons/python3.8
Creating virtualenv at: hoge

このように uv venv が動くようになるだけでなく、 uv venv -p3.x で rye が管理しているインタープリタを利用できるようになりました。 上のコマンドはすごく雑なやり方で、 3.12.0 と 3.12.1 のようにマイクロバージョン違いのバージョンが複数ある場合はどれが利用されるかわからないので、その場合は手作業で修正してください。

Ryeの中のuvを使う

python

uvにはまだ self update の機能がありません。 Homebrewにはすでにuvが追加されて頻繁にアップデートされているので、Homebrewユーザーは brew install uv がおすすめです。

Homebrewを使ってない環境でuvをインストールし手軽にアップデートするには 、rye install pipx か brew install pipx した上で pipx install uv するのがおすすめです。 Rye自体にも rye install コマンドはありますが、まだpipxほどは使い勝手がよくありません。 (pipx upgrade-all 相当ができない)

裏技として、Ryeでuvを有効にする(rye config --set-bool behavior.use-uv=true)とRyeの内部にuvもインストールされるので、それを直接使うこともできます。Ryeはuvほどではないものの頻繁にアップデートされ、self update機能(rye self update)もあるので、ryeのおまけでuvがアップデートされるのは便利です。rye fmt/rye lintが使っているruffにも同じテクニックが使えます。

$HOME/.rye/self というディレクトリが Ryeが内部に持っているPythonのvenvになっているので、その中のコマンドへPATHが通っているディレクトリからsymlinkを作ってやります。次の例では $HOME/.local/bin を使っています。

cd ~/.local/bin
ln ~/.rye/self/bin/uv
ln ~/.rye/self/bin/ruff

ryeの中にuvがインストールされるのはuvを有効にしたあと、一度でもrye addなどのコマンドを実行する必要があるのに注意が必要です。 試しにすでに0.25がインストールされてる状態で rye config --set-bool behavior.use-uv=true; rye self update してみたのですが、 uv はインストールされていませんでした。実際にryeのバージョンが上がるタイミングでは uv がインストールされるかもしれませんが、未確認です。

このブログに乗せているコードは引用を除き CC0 1.0 で提供します。