届かなかったのと、起きなかったのは別だ

一言でいうと

ログが空いているとき、「届かなかった」と「何も起きなかった」を分けるのは、時刻ではなく送信側が付けた番号です。番号がなければ欠落は永遠に証明されず、番号があっても再起動の前では、うそをつきます。

なぜ必要なのか

収集器に溜まったログを見て「この5分間はリクエストがなかった」と言った瞬間、私たちは証明できないことを言ったことになります。リクエストがなかったのかもしれませんし、リクエストはあったのに、その行が届く途中で消えたのかもしれません。この2つは結論が正反対なのに、ファイルだけを見ても区別できません。

RFC 5424は8.5節で、これをとてもはっきり書いています。syslogプロトコルには配信を保証する仕組みがなく、下位の転送(UDPのような)も不安定なので、一部のメッセージはそのまま消えることがあります。そして、同じ節は、もっと不都合な話を付け加えています。信頼性のある配信が、常に望ましいわけでもないというのです。受信者がこれ以上受け取れないとき、送信者が止まる必要がありますが、Unixではsyslogdは優先度の高いシステムプロセスなので、それが止まるとシステム全体が止まります。そのため、現実的な実装は、止まる代わりに、意図的に捨て、捨てたという事実を知らせます。何の表示もなく消えるよりは、そのほうがよいというのです。

サイズも理由になります。同じ文書の6.1節は、転送の受信者が最小480オクテットだけ対応すればよく、2048オクテットを超えるメッセージは、切ってもよく、捨ててもよいと書いています。そのため、8.3節は、重要な情報をメッセージの前のほうに置くよう勧めています。後ろは切れることがあるからです。

どう動くのか

欠落を数える唯一の方法は、送信側の単調増加の番号です。送る側がseqを付け、どこまで送ったかを定期的に知らせてくれれば、受け取った番号の集合と送った範囲を引くだけで、何が欠けたかが出ます。区間にまとめて見ると、さらに役に立ちます。散らばった1件ずつの損失と、50件が1つの塊として欠けたものは、原因が違います。

ところが、番号は再起動で巻き戻ります。プロセスが再び立ち上がると、seqはまた1からです。そのため、番号だけで同じ行を判定すると、2つのことが同時に崩れます。再起動の前後の同じ番号が重複に見え、再起動後に欠けた番号は、再起動前の記録に隠れて、欠落ではないように見えます。解決策は1つです。番号にブート識別子を一緒に結び付けます。systemdのジャーナルが_BOOT_IDを残す理由でもあります。

同じ行が2度来るのは、正常です。応答を受け取れなかった送信者が再送すれば、受信者は同じ行を2度受け取ります(at-least-once)。このとき必要なのは、「何を同じ行と見なすか」の定義です。(ホスト、ブート識別子、番号)があれば、それが答えで、なければ内容のフィンガープリントを使うことになりますが、そうすると、本当にまったく同じ2つの出来事まで、1つに畳まれてしまいます。

受け取った順序は、起きた順序ではありません。収集の経路が詰まると、行は数分後に届きます。OpenTelemetryのログデータモデルが、時刻フィールドを2つに分けている理由が、これです。Timestampは、出来事が起きた時刻を、元の時計で測ったもので、ObservedTimestampは、収集側がその出来事を観測した時刻です。規格は、時刻を1つしか入れられない形式に移すとき、「Timestampがあればそれを、なければObservedTimestampを」使うよう勧めています。2つの差が、そのまま到着遅延で、その分布を見れば、収集経路の健康状態が見えます。

現場での姿

締め切り時刻が数字を変えます。「昨日のエラーは何件だったか」を、真夜中の直後に数えると、まだ届いていない行は抜けます。数日後に同じクエリを実行すると、数字が増えます。バグではなく、遅れて届いたのです。そのため、集計には締め切り猶予(late window)が必要で、その猶予は、遅延分布のp95やp99を見て決めます。

保管を延ばしても、来ない行があります。journald.conf(5)のRateLimitIntervalSec=とRateLimitBurst=は、1つのサービスが決められた区間の中で、決められた数より多く出力すると、その区間の残りを捨てます。デフォルトは30秒に10000件で、サービスごとに適用され、捨てた数を知らせるメッセージが残ります。障害でログが急増するまさにその瞬間に、最も多く捨てられます。

欠落率は、区間ごとに違います。全体で6パーセントという数字は、たいてい役に立ちません。どの5分間に50件がまるごと欠けたかが重要で、その区間が事故の区間と重なるかが、結論を変えます。

次のラボですること

収集器が受け取ったファイルと、送信側のカウンターを一緒に作り、2つを突き合わせて欠落を数えます。欠けた番号を区間にまとめ、at-least-onceが作った重複を畳み、到着遅延の分布を求めます。そのあと、締め切り時刻に集計していたら何件を見逃していたかを計算し、最後に、再起動で番号が巻き戻ったホストで、ブート識別子を無視すると、欠落と重複がどのように入れ替わるかを、数字で示します。