👻
OpenTelemetry Collector の Filelog Receiver とログローテーションについて

2024/12/07に公開
Kubernetes
こんにちはー。年末ですねえ。
OpenTelmetry Advent Calendar 2024 および Splunk Advent Calendar 2024 の 7 日目の記事です。
https://qiita.com/advent-calendar/2024/opentelemetry

https://qiita.com/advent-calendar/2024/splunk
今回は、OpenTelemetry Collector の Filelog Receiver とログローテーションについて、調べていた内容をまとめてみました。

いざ書き出すと、なかなかの分量になってしまいました。
!Github上のドキュメントなどを参照しつつまとめています。内容は意訳ですので、原文も同時に参照してください。

また、より正確な表現や和訳に関する指摘があればコメントにてお願いします。

 OpenTelemetry におけるログ取得OpenTelemetry はオブザーバビリティに欠かせないテレメトリーデータの管理に関するスタンダードとして、多くのエンジニアにとって頼れるツールになりつつあると思います。
OpenTelemetry が扱うテレメトリーデータとして、メトリクス、トレース、ログ、プロファイルが挙げられますが、今回はこの中でもログにフォーカスを当ててみます。
OpenTelemetry においてログ収集を担う代表的な Receiver は、Filelog Receiver です。その名の通り、ファイルに出力されているログを追跡してくれます。

GitHubのレポジトリはこちら。

https://github.com/open-telemetry/opentelemetry-collector-contrib/blob/main/receiver/filelogreceiver/

 Filelog Receiver
 基本的な使い方ご存じの通り、OpenTelemetry Collectorは、Receiver でデータを収集し、Processor でデータを加工、Exporter で転送するというパイプラインを構築します。

ここでは Filelog Receiver を使って、シンプルなログ収集の設定例を見ていきます。
receivers:
  filelog:
    include: [ /var/log/myservice/*.json ]
    operators:
      - type: json_parser
        timestamp:
          parse_from: attributes.time
          layout: '%Y-%m-%d %H:%M:%S'

exporters:
  otlp:
    endpoint: hogehoge:443

services:
  pipelines:
    logs:
      receivers: [filelog]
      processors: []
      exporters: [otlp]
receivers.filelog で Filelog Receiver を宣言し、以下で具体的な設定を行っています。

ここでは、基本的な設定項目を扱っていますが、それぞれ以下のようなことをやっています。

include: 監視対象のログファイルを指定します。ここでは /var/log/myservice/*.json に合致するログファイルが対象です。

operators: ログデータをパース・変換するオペレーションの一覧です。この例では、正規表現でログを解析し、タイムスタンプとログレベルを抽出しています。
このパイプラインでは、processors は利用せず、exporters.otlp.endpoint で指定したエンドポイントに OTLP で送信を行っています。

最後に service.pipelines.logsで、Filelog Receiver と OTLP Exporter をパイプラインとして構成しています。

 Splunk Distro of OpenTelemetry Collector for K8s の場合ちなみに、Splunk が提供している Distribution の Kubernetes 向け OpenTelemetry Collector を利用すると、最初から以下のような設定が入ってきます。

一部を抜粋してご紹介。
receivers:
  filelog:
    encoding: utf-8
    exclude:
    - /var/log/pods/default_splunk-otel-collector*_*/otel-collector/*.log
    # 中略
    include:
    - /var/log/pods/*/*/*.log
    operators:
    - id: get-format
      routes:
      - expr: body matches "^\\{"
        output: parser-docker
      - expr: body matches "^[^ Z]+ "
        output: parser-crio
      - expr: body matches "^[^ ]+ "
        output: parser-containerd
      type: router
    # 中略
    poll_interval: 200ms
    retry_on_failure:
      enabled: true
    start_at: beginning
    storage: file_storage
デフォルトでは、Kubernetes 環境におけるログとしては include にて /var/log/pods/*/*/*.log を参照するようになっています。

filelog.operators には、さまざまなパースやフィールド調整の設定が入っています（量が多いの略しています）。

このあたり、ある程度推奨設定が入っているので、これらを参考にしながら調整していっていただくとよさそうです。

 ログのオフセットトラッキング対象ログのうち、どの位置まで Filelog Receiver が受信したか、送信がどこまで行われたかは、いずれもデフォルトでは OpenTelemetry Collector のメモリ上に保持されます。

つまり、OTel Collector の再起動が行われると、それらのデータは消失してしまいます。

これを防ぐために、storege Extention を利用した永続キューを指定することができるようになっています。

Filelog Receiver の Offset tracking から、リンクをたどっていくと、以下のようなサンプルコードを見つけることができるはずです。
receivers:
  filelog:
    include: [/var/log/busybox/simple.log]
    storage: file_storage/filelogreceiver

extensions:
  file_storage/filelogreceiver:
    directory: /var/lib/otelcol/file_storage/receiver
  file_storage/otlpoutput:
    directory: /var/lib/otelcol/file_storage/output

service:
  extensions: [file_storage/filelogreceiver, file_storage/otlpoutput]
  pipelines:
    logs:
      receivers: [filelog]
      exporters: [otlp/custom]
      processors: []

exporters:
  otlp/custom:
    endpoint: http://0.0.0.0:4242
    sending_queue:
      storage: file_storage/otlpoutput
extensions.file_storage/filelogreceiver と extensions.file_storage/otlpoutput という Extension が作成されています。それぞれ、/var/lib/otelcol/file_storage/ 以下のディレクトリを指定してあります。

この Extension を receivers.filelog.storage および exporters.otlp/custom.sending_queue.storage として指定しています。

つまり、Filelog Receiver は、対象ログをどこまで読み取ったかを管理するファイルを /var/lib/otelcol/file_storage/receiver に保持するようになり、OTLP Exporter についても、送信キューを永続ストレージである /var/lib/otelcol/file_storage/output を利用するようになったということです。

これで、仮に OTel Collector が何らかの理由で再起動されたりしても、このオフセットファイルを用いてトラッキングができるようになったということになります。
なお、オフセットファイルは、バイナリファイルで、ターミナルから cat などで（無理やり）参照するとこんな感じに見えます。

（以下は、Splunk Distro の OTel Collector for K8s におけるデフォルトのオフセットファイルから抜き出し）
/var/addon/splunk/otel_pos/receiver_filelog_
（文字化け表示される諸々）
file_input.knownFiles52
{"Fingerprint":{"FirstBytes":"MjAyNC0....xxxXX"},"Offset":334077,"FileAttributes":{"log.file.path":"/var/log/pods/kube-system_coredns-77ccd57875-7rp4x_2812e9fd-2a75-4f1b-a113-f5a426332c49/coredns/175.log"},"HeaderFinalized":false,"FlushState":null}
...
knownFiles はトラッキングされているファイルの数で、Fingerprint の中の FirstBytes はフィンガープリント、Offset はファイルの最初からのバイト位置、FileAttributes はファイルに関する諸々の情報ですね。

 OpenTelemetry Collector とログローテーションログファイルがいつまでも膨張を続けるのは好ましくありません。必ずローテーションを設定するはずです。

では、Filelog Receiver もまた、ローテーションに対応し、ファイルを何らかの方法でトラッキングできる必要があります。
ローテーションへの対応について、詳細に書かれたドキュメントがあります。

該当箇所を抜粋すると、以下の4ケースの挙動をサポートするもののようです。
A）未読ログが末尾にある状態でファイルマッチングのパターン内でファイルが移動され、その後、元のファイルを再度作成した場合、移動されたファイルの未読ログ・新しく作成されたファイルに書き込まれた新しいログが共に取得される
B）未読ログが末尾にある状態でファイルマッチングのパターン内でファイルがコピーされ、その後、元のファイルがトランケートされた場合、コピーされたファイルの未読ログ・トランケートされたファイルに書き込まれた新しいログが共に取得される
C）ファイルがファイルマッチングのパターン外に移動・作成される形でローテートされた場合、古いハンドルが有効であることを検出し、ローテートされたファイルから読み出しを試みる
D）ファイルがファイルマッチングのパターン外にコピー・トランケートされる形でローテートされた場合、古いハンドルが無効であることを検出し、ローテートされたファイルから読み出しを行わない
この挙動を理解する上では、OpenTelemetry Collector がどのようにしてファイルを一意のものと判断しているか、という点を理解しておく必要があります。

（上で触れた、Fingerprint などもここに関わってきます）
本ドキュメントに記載されいている内容を、以下では抜粋しながら見てみます。

 File MatchingFilelog Receiver などが読み出す対象ファイルか否かを判定する方法が書かれています。

シンプルですが、

include で指定したパターンに一致していて、

exclude で指定したパターンに一致しないファイル
が matched files と判定されます。まあ、それはそうですよね。

 Fingerprintsファイルの識別とトラッキングにはフィンガープリントが利用されます。
ファイルの最初の N バイト（デフォルトは1000バイト）をフィンガープリントとして識別

N バイト以下の場合はファイル全体が対象

同一のフィンガープリントを持つ場合は重複ファイルとして、片方のみを処理する
ローテーションの際にコピー・トランケートを行うと、一時的に全く同一のフィンガープリントのファイルが生成されるため、これに対応しているようです

また、ローテーションに際してのオフセットトラッキングに関して以下が明記されています。
ローテーションによってファイル名が対象外になる場合は、新規ファイルの読み取りの前に、ローテーションされたファイルを最後まで読み取ろうとする
以下の場合は、ローテーション間でのログ行の順序が保証される
ローテーションされたファイル名が、対象パターンと一致しておらず
ローテーションされたファイルに、ローテーション後に書き込みが行われない

これらは、後続の Readers や Polling に関するデザインによって実装されているようです

 Readersファイルと関連するメタデータを管理するのが Reader です。

フィンガープリントやオフセット、ファイルパスなどのメタデータから、読み込む対象ファイルを特定し、実際に読み込みをやっていきます。
この Reader は、ファイルのハンドル（オープン・クローズ）に関わりますが、ファイルクローズと共に破棄されるのではありません。

一定のポーリングサイクルの間は維持されることで、ファイルの移動などを検出できるようになっているそうです。

 PollingPolling は、指定した間隔で、定期的にファイルシステムへのスキャンを行うものです。

一連のポーリングにおける処理（キューに関する処理や、ファイルマッチング、Reader の作成とファイルの読み取り・クローズ、Reader の履歴管理など）をサイクリックに実行していきます。

この中でログローテーションと関わりがある項目として、以下の記載があります。
Reader Creation
Reader作成時には、かつて検出された Fingerprint が相互参照される
既に検出されたことのある Fingerprint と一致する場合、メタデータは過去のポーリングサイクルの際に記録されたものからコピーされる
直近で検出されたファイルと Fingerprint が一致しない場合、start_at の設定に基づいてオフセットが初期化される
Detection of Lost Files
フィンガープリントが前回のサイクルで一致したが今回は一致しないファイルは "lost files" と呼ばれる
これは、ファイルの削除や、ローテーションによって生じることがある
前回のポーリングサイクルで開いたファイルハンドルが役立つことがある

Consumption
"Lost file" が読み込まれる。削除された場合は失敗することがあるが、ファイルの移動の場合は、コンテンツの残りを読み込むことができる可能性がある
つまり、あるポーリングサイクルで検出したフィンガープリントと、前回のサイクルで検出したフィンガープリントとを踏まえて、ファイルを一意のものと判定しており、

また、"Lost File" を検知したら、移動されたファイルのコンテンツを読み出しに行くということですね。
なお、スタートアップ・シャットダウン時の挙動についてもまとめられていますが、

起動時には過去のサイクルにおける Reader の履歴を確認するし、停止時には現在読み込み中のファイルを消費しきって、どこまで読んだかなどを保存する、というようなことが書かれています。

 ログローテーションにおける Supported Case についてこれらの内部的な設計を踏まえた形で、ログローテーションにおける挙動が説明されています。
ファイルマッチングパターン内でローテーションされると、古い Reader は閉じられ、新規の Reader がローテーションされたファイルを差して生成されますが、過去のメタデータが引き継がれる
ファイルマッチングパターン外のファイル移動される場合は、古いファイルハンドルが移動後のファイルを指すのでログの消費が可能
ファイルマッチングパターン外にコピー/トランケートされる場合、古いファイルハンドルがトランケートされた元ファイルを指すので、コピーされたファイルをハンドルすることができない

 Kubernetes 上のコンテナログのローテーションの場合では、Kubernetes 上で実行されるコンテナの場合、どうなるのでしょうか。
コンテナが標準出力・標準エラー出力にログ出力している場合、そのコンテナが実行されているノード上のディレクトリ、具体的には /var/log/pods/<namespace_name>_<pod_name>_<uid>/<container_name>/*.log に記録されています。

このファイルは、0.log からはじまり、コンテナの再起動に合わせて、1→2... とカウントアップされていきます。

一方で、kubelet の設定に応じて、一定のサイズになると、0.log.yyyymmmdd-hhmmss にローテートされ、さらにもう一世代前のローテートログは Gzip で圧縮されます。
$ ls -lh /var/log/pods/default_splunk-otel-collector-agent-t8dqx_efe55665-3e79-4055-bdbf-ee37409d40d9/otel-collector/
total 34M
-rw-r----- 1 root root 108K Nov 19 21:44 0.log
-rw-r--r-- 1 root root 781K Nov 19 20:39 0.log.20241119-200634.gz
-rw-r--r-- 1 root root 781K Nov 19 21:12 0.log.20241119-203920.gz
-rw-r--r-- 1 root root 772K Nov 19 21:44 0.log.20241119-211216.gz
-rw-r----- 1 root root  11M Nov 19 21:44 0.log.20241119-214432
-rw-r----- 1 root root 8.8M Dec  6 02:49 1.log
-rw-r--r-- 1 root root 779K Dec  6 01:15 1.log.20241206-004213.gz
-rw-r--r-- 1 root root 775K Dec  6 01:48 1.log.20241206-011527.gz
-rw-r--r-- 1 root root 760K Dec  6 02:21 1.log.20241206-014822.gz
-rw-r----- 1 root root  11M Dec  6 02:21 1.log.20241206-022106
Kubernetesにおけるログローテーションの実装は（ソースコード）、
一時ファイル、前回のローテートの失敗などをクリーンアップ
最大保持ファイル数を超える古いログを削除
（1世代前の）非圧縮状態のログを圧縮
ローテーションを実行
となっており、特にこの 4.ローテーション は、以下のように osInterface.Rename を呼び出しています（ソースコード）
container_log_manager.go
// rotateLatestLog rotates latest log without compression, so that container can still write
// and fluentd can finish reading.
func (c *containerLogManager) rotateLatestLog(id, log string) error {
	timestamp := c.clock.Now().Format(timestampFormat)
	rotated := fmt.Sprintf("%s.%s", log, timestamp)
	if err := c.osInterface.Rename(log, rotated); err != nil {
		return fmt.Errorf("failed to rotate log %q to %q: %v", log, rotated, err)
	}
	if err := c.runtimeService.ReopenContainerLog(id); err != nil {
		// Rename the rotated log back, so that we can try rotating it again
		// next round.
		// If kubelet gets restarted at this point, we'll lose original log.
		if renameErr := c.osInterface.Rename(rotated, log); renameErr != nil {
			// This shouldn't happen.
			// Report an error if this happens, because we will lose original
			// log.
			klog.ErrorS(renameErr, "Failed to rename rotated log", "rotatedLog", rotated, "newLog", log, "containerID", id)
		}
		return fmt.Errorf("failed to reopen container log %q: %v", id, err)
	}
	return nil
}
osInterface.Rename は、os.Rename を呼び出しており（ソースコード）、ファイルの移動が発生しているということになります。
os.go
// Rename will call os.Rename to rename a file.
func (RealOS) Rename(oldpath, newpath string) error {
	return os.Rename(oldpath, newpath)
}
というわけで、冒頭での Splunk Distro of OpenTelemetry Collector for Kubernetes では、receivers.filelog.include として /var/log/pods/*/*/*.log を指定していました。

そのため、
書き込みされていくログファイルはパターンマッチした状態
コンテナ再起動によって生成されるログもパターンマッチした状態
ログローテーションが発生すると、パターンマッチ外にファイルが移動する形になるが、これは Supported Case (C) に当てはまる
古いファイルハンドルに基づいて、移動によってローテーションされたファイルの末尾まで読み込みが行われる
圧縮済みのファイルに関してはパターンマッチ外なので、対象外

という感じの動きになるということが分かるはずです。ローテーションについても上手に扱っていそうですね。

もちろん、例えば、ローテートされたファイルが圧縮されるまでの間に読みだされないような状態が起きたりする（OTel Col がエラーで再起動を繰り返したりとか…）と、その分のログは取得できなくなる可能性がありますので、注意が必要です。

 まとめログのトラッキングとローテーションは、少なからぬ場面で詳細な議論が必要になってきたと思います。

OpenTelemetryにおける挙動も正しく把握しながら、オブザーバビリティをたかめていきたいものですね。
Kuberenetesにおけるログ管理については、以下のブログも参考にさせていただきました。ありがとうございました。

Kubeletのログ管理を追ってみる
OpenTelemetry におけるログ取得

Filelog Receiver

基本的な使い方

Splunk Distro of OpenTelemetry Collector for K8s の場合

ログのオフセットトラッキング

OpenTelemetry Collector とログローテーション

File Matching

Fingerprints

Readers

Polling

ログローテーションにおける Supported Case について

Kubernetes 上のコンテナログのローテーションの場合

まとめ

Discussion
