net.ConnのReadとWriteの振る舞いについて

Go-MySQL-DriverでカスタムのDialをサポートしていたり圧縮プロトコルサポートのコードをレビューしていたりして、利用している Write() の実装が多様化してきたので、「Write(p)って Read(p)みたいに n が len(p) より小さい場合にループで続きを書き込まなくてい良いのは決まりがあったっけ?」と気になって確認してみました。

まず、 net.Conn の定義ではReadとWriteは次のようになっています。

// https://pkg.go.dev/net#Conn

type Conn interface {
    // Read reads data from the connection.
    // Read can be made to time out and return an error after a fixed
    // time limit; see SetDeadline and SetReadDeadline.
    Read(b []byte) (n int, err error)

    // Write writes data to the connection.
    // Write can be made to time out and return an error after a fixed
    // time limit; see SetDeadline and SetWriteDeadline.
    Write(b []byte) (n int, err error)

ここには n と err の関係どころか n の意味自体書かれていません。実際には net.Conn のReadとWriteは io.Readerio.Writer を満たしているので、そちらのドキュメントを見る必要があります。

https://pkg.go.dev/io#Reader

Reader is the interface that wraps the basic Read method.

Read reads up to len(p) bytes into p. It returns the number of bytes read (0 <= n <= len(p)) and any error encountered. Even if Read returns n < len(p), it may use all of p as scratch space during the call. If some data is available but not len(p) bytes, Read conventionally returns what is available instead of waiting for more.

(略)

https://pkg.go.dev/io#Writer

Writer is the interface that wraps the basic Write method.

Write writes len(p) bytes from p to the underlying data stream. It returns the number of bytes written from p (0 <= n <= len(p)) and any error encountered that caused the write to stop early. Write must return a non-nil error if it returns n < len(p). Write must not modify the slice data, even temporarily.

まとめると次のようになります。

Readの場合

  • 現時点で得られたデータが len(p) よりも少ない場合は、後続のデータを待たずに n < len(p) を返すのが一般的(待っても良い)。
  • n > 0 かつ err != nil の場合があるので、 err をチェックする前に p[:n] までのデータを処理する必要がある。
    • 特に err == io.EOF の場合は正常系として頻出する。
  • Readの実装は、 n にかかわらず、 p 全体を一時メモリとして利用可能。

Writeの場合

  • n < len(p) の場合は errnil でないことが保証されている。
    • つまり、呼び出し側は err == nil の時に改めて p[n:] を書き込む必要はない。
    • そのため、 io.WriteFull() などは存在しない。
  • n > 0 かつ err != nil の場合があるのはReadと同じ。
    • ただしReadと違って正常系の err == io.EOF が無いので、途中までデータが書き込めたことに対して何か処理が必要で無い限りは無視していい。
  • Writeは p に対して一切書き込みを行わない。

ということで、Writeの方が使う側にとってはかなりシンプルですね。

Go-MySQL-Driver v1.8.0 をリリースしました

github.com/go-sql-driver/mysql (a.k.a. Go-MySQL-Driver)のv1.8.0をリリースしました。

個人的に重要だと思う点を紹介していきます。

charset/collationの扱い

ちょうどGREEさんのBlogで話題になっていた件です。

go-sql-driver/mysqlMySQL 8.0 もデフォルトのままだと、collation_connectionはutf8mb4_general_ci、collation_serverはutf8mb4_0900_ai_ciになります。いずれも character set としてはutf8mb4ですが、utf8mb4_general_ciとutf8mb4_0900_ai_ciは振る舞いが大きく異なるので、Goでutf8mb4を使うなら、意図したcollationが適用されているか注意が必要です。

v1.7まではREADMEに次のように書かれていました。

Version 1.0 of the driver recommended adding &charset=utf8 (alias for SET NAMES utf8) to the DSN to enable proper UTF-8 support. This is not necessary anymore. The collation parameter should be preferred to set another collation / charset than the default.

DSNで charset を指定するのは非推奨で collation を書け、ということですね。ハンドシェイクではそのcollationに対応したcollation idを使います。 charset を指定した場合はそのcharsetに対するデフォルトのcollationを選びますし、両方を指定した場合は collation が優先されました。

これには、 collation を理解して正しく設定しないといけないという問題と、ドライバー側でサーバーと一致したcollationの名前とidのマッピングを持っていないといけないという問題がありました。MySQL 8がどんどん進化する中、MySQLプロトコルを利用する他の製品も多様化していくので、問題は徐々に悪化してきました。

v1.8では charset を指定したときの動作が変わります。ハンドシェイクでデフォルトのcollation_idを送るのはそのままですが、接続後に SET NAMES <charset> を実行するので、そのcharsetに対するサーバー側のデフォルトのcollationが利用されます。 skip-character-set-client-handshake や、指定したcollation_idをサーバーが知らなかったなどの理由で暗黙のうちに完全に無視されることはありません。そのcharsetをサーバーが知らないならちゃんとエラーになります。

ということで、サーバー側のデフォルトのcollationをそのまま使えばいいほとんどのケースで、 charset のみを指定する設定を推奨します。 collation も指定したい場合は、charsetとcollationの両方を指定してやれば、 SET NAMES <charset> COLLATE <collation> というクエリを実行するので、確実にそのcollationを使えます。

より詳しい解説を去年Zennで MySQL接続のcollation不整合の原因と対策 という記事を書いたので読んでみてください。

Scan()にanyを渡した時の挙動を改善しました。

v1.7では次のように、内部でテキストプロトコルが使われているかバイナリプロトコルが使われているかでanyにScan()した時の結果が異なりました。

// db の接続設定で interpolateParams が false の場合
var v any
db.QueryRow("SELECT 123 WHERE ? = 1", 1).Scan(&v)
fmt.Printf("%T %v\n", v, v)  // int64 123

db.QueryRow("SELECT 123 WHERE 1 = 1").Scan(&v)
fmt.Printf("%T %v\n", v, v)  // []uint8 [49 50 51]

整数やfloatなど、変換してもアロケーションが増えない型に限定して、テキストプロトコルでもバイナリプロトコルと同じ結果になるようにしました。

これも詳細は去年Zennに書いたので、Go-MySQL-DriverでScan()にanyを渡した時の挙動を改善しました を読んでみてください。

構造化ログから構造化イベントへ

オブザーバビリティ・エンジニアリングの5章のタイトルは「構造化イベントはオブザーバビリティの構成要素である」です。構造化イベントの定義は5.1節にあります。

イベント とは、本番環境のサービスへの影響を理解するために、ある特定のリクエストがそのサービスとやりとりしている間に発生したすべての記録です。

そこからさらにイベントの記録について説明が続きます。

空のマップを初期化することから始めます。このマップには、そのリクエストの有効期間中に発生したものに関する興味深い詳細、 たとえばユニークID、変数の値、ヘッダー、リクエストで渡されたすべてのパラメーター、実行時間、リモートサービスへのコール、それらのリモートコールの実行時間など、後にデバッグに役立つであろうあらゆるコンテキストが追加されます。 そして、リクエストが終了したりエラーが発生したりすると、そのマップ全体はリッチな情報として取得されます。

つまり、ログを1リクエストあたり1行まで減らす代わりに、ログのカラムを大幅に増やすのです。

構造化イベントという用語はオブザーバビリティ・エンジニアリングの著者が所属している honeycomb.io が利用している用語のようですが、広く定着しているわけでは無さそうです。同じプラクティスにStripeはCanonical Log Linesという名前を使っているようです。

brandur.org

structlogのドキュメントのBest PracticesでもCanonical Log Linesが紹介されています。

www.structlog.org

さて、ここを見るとCanonical Log Linesを実現するためにbindが使えそうに書いてあります。

structlog’s ability to bind data to loggers incrementally (snip) can help you to minimize the output to a single log entry.

しかし、 log.bind() の動作は(GoのContextのような)スタック型になっていて、リクエストの処理の最後にまとめて書き出すために属性を追記していくのには向きません。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    log = logger.bind(foo="bar")
    log.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"arg": "world", "event": "goodby"}

このサンプルでは foo="bar" が最後のログに反映されていません。これでは hello() の中でログを書くのをやめられません。

このスタック型にkey-valueを積み重ねていく設計は、immutableで一般的にはセンスの良いものですが、構造化イベントを実現するのに向いているとは思えません。

structlogのドキュメントではあまり言及されていない structlog.get_context() というAPIを使えば、loggerが持っているbind()済み変数が保存されたdict(=Context)を直接編集できるので、追記型の振る舞いも実現できます。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    lg = structlog.get_context(logger)
    lg["foo"] = "bar"
    logger.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"foo": "bar", "arg": "world", "event": "goodby"}

このサンプルで最後に "foo": "bar" が出力されているので、hello()の中のログを消せるようになりました。 このとき、 lg["foo"] = "bar" の部分は lg["hello.foo"] = "bar"lg["hello"] = {"foo": "bar"} と書き換えると良いと思います。

構造化イベントのサポートが弱いのは、structlogだけではなく多くの構造化ログライブラリに共通する点だと思います。しかし、リクエストスコープのコンテキストを持つ仕組みは一般的なので、構造化イベントの実装は難しくありません。

例えばFlaskであれば flask.g.log_event = {} みたいな辞書を用意して、そこにイベントを足していけば良いでしょう。この仕組みなら、Goでもリクエストの先頭でContext にイベント追記用の map か sync.Map を格納すれば良いでしょう。

ここまで構造化イベントをベストプラクティスとして紹介してきましたが、私は全てのログを構造化イベントにまとめるべきだとは思っていません。メトリクスを抽出したり、ユーザーの行動分析に役立つ要素なら構造化イベントが適していると思いますが、デバッグに役立つ中間値や分岐を残すログであったり、パフォーマンス分析のためにタイミングを記録するログまで構造化イベントにする必要はないでしょう。

そのようなログは、リクエストIDと限られた属性だけをbindしたカラムの少ないログをデバッグレベルで出力するとか、トレーシングを使っているならトレースの属性やイベントとして記録するのが良いでしょう。ログを分けることで、保存期間を分けたり、異なるサンプリングをできます。たとえば構造化イベントは全てのログに対してとってアクセスログと同じ期間記録し、デバッグやパフォーマンス分析用のログはトレースと一緒にサンプリングしてより短い期間で破棄すると良いでしょう。

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

みんな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を使っておいた方が良いと思います。

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