長いログを強制的に改行しているのは誰？： Rails / Passenger / Docker / GKE

現在とある Rails アプリを Google Kubernetes Engine (GKE) 上で動かしています。アプリケーションのログは JSON 形式で標準出力に流し、 Cloud Logging で[構造化ログ](https://cloud.google.com/logging/docs/structured-logging?hl=ja)として検索しやすくしてあります。

> Google Kubernetes Engine または App Engine フレキシブル環境を使用している場合は、構造化されたログを 1 行でシリアル化された JSON オブジェクトとして `stdout` または `stderr` に書き込めます。すると、構造化ログは、Logging エージェントにより、`LogEntry` 構造の `jsonPayload` として Cloud Logging に送信されます。

しかしたまに出力される長いログは、 JSON が **8192 バイト毎に改行が入り複数行に分断**されていて、構造化ログと認識されていません。現状はとくに問題となっていないものの、全て構造化ログになっていると思って検索するとログを見落としてしまう恐れがあります。

---

稼働中のアプリでログ出力に関わっている登場人物は、大雑把には以下の通りです。
Rails → Ruby →[^app-log] Passenger → (Nginx)[^ng] →[^srv-log] Docker → GKE → Cloud Logging

この中でいつ改行されてしまうのか調査しました。

[^app-log]: Rails のログは、ログファイルを作らないよう標準出力に流しています。それを起動元の Passenger が拾って再処理します。
[^ng]: Passenger のログ出力先を Nginx のログファイルにしているだけであり、 Nginx はアプリのログを処理していないかもしれません。
[^srv-log]: Nginx のログファイルを `/dev/stdout` へのシンボリックリンクにして、標準出力に流しています。

## TL;DR
Passenger が改行しているようです。アプリの標準出力を転記する処理の中に **8192 バイトのバッファ**が存在し、それを超える分は次の行として出力している様子でした。
https://github.com/phusion/passenger/blob/release-6.0.15/src/agent/Core/SpawningKit/PipeWatcher.h

```cpp:PipeWatcher.h
	void threadMain() {
		...

		UPDATE_TRACE_POINT();
		while (!boost::this_thread::interruption_requested()) {
			char buf[1024 * 8];
			ssize_t ret;

			UPDATE_TRACE_POINT();
			ret = syscalls::read(fd, buf, sizeof(buf));
			...
```

そして**既に issue や pull request がありました**。 Passenger 6.0.17 でこのバッファサイズは設定可能になったみたいです。~~わざわざコードを追う必要なかった…~~

https://github.com/phusion/passenger/issues/2413

---

念のため他の部分も検証しましたが、 Rails アプリ（で使う Ruby の Logger ）はログ出力が 8192 バイトを超えても改行せず、また Docker コンテナから Cloud Logging までの間も 8192 バイトを超えて処理できました。

## ログ出力を区切って調査
ログ出力の流れを再掲します。
Rails → Ruby →[^app-log] Passenger → (Nginx)[^ng] →[^srv-log] Docker → GKE → Cloud Logging

※ Docker のベースイメージに [passenger-docker](https://github.com/phusion/passenger-docker) の Ruby イメージを用いています。

全ての処理を通った結果のログを見るだけでは調べにくいので、中間でログを見たり、中間からログを流したりしてみます。

### Docker のコンテナログを確認
Kubernetes 上で動かしている場合、コンテナのログは `kubectl logs` コマンドで確認できます。

```bash
kubectl logs {pod名} | less

# ログの時刻をもとに出力を絞り込む場合
kubectl logs {pod名} --since-time='2023-10-19T01:23:45Z' | head -n 10
```

この結果、ログは 8192 バイトで改行されていました。つまり **Rails 〜 Docker のどこか**で既に改行が入り込んでいます。 GKE 周辺の問題でないのなら、ローカル環境で適当なコンテナを作って試していけます。

※ 検証のために使った `kubectl logs` によって初めて改行された可能性もありますが、これの影響でないことは次節の方法で確認できます。

### Docker コンテナにログ注入
Docker 〜 Cloud Logging の間では問題ないことも念のため確認したいです。ウェブアプリを介さず**コンテナ上で直接ログを生成・注入**できれば確認できるはずですが、それは可能なのでしょうか？

コンテナログは、プロセスの標準出力と標準エラー出力を拾っています。しかし、普通にコンテナに入って `echo` などで出力しても、ターミナルに出力されるだけでコンテナログには出力されません。

```bash
# 稼働中のコンテナに入る
kubectl exec -it {pod名} -- bash

# 標準出力に出してみる → ターミナルに出力される
echo 'test'
#=> test
```

調べたところ、コンテナログと扱わせるには **`/proc/1/fd/1`** （プロセスIDの1番にとっての標準出力）に対して出力すればいいらしいです。

https://stackoverflow.com/questions/58716574

```bash
kubectl exec -it {pod名} -- bash

cat << EOF > /proc/1/fd/1
（ 8192 バイトを超える1行の文字列をここに貼る）
EOF
```

すると入力したログは改行されずに、コンテナログや Cloud Logging で表示されました。

### Rails のログを確認
アプリケーション（ Rails ）とサーバ（ Passenger と Nginx ）のどちらが改行を入れているのか切り分けます。ここからは適当なサンプルアプリで試しています。

実際のアプリに合わせて [Logger](https://docs.ruby-lang.org/ja/latest/library/logger.html) の出力先を標準出力に設定し、適当なタイミングで 8200 バイトの文字列を書き出してみます。（ログの付加情報のぶんだけ更に長くなります）

```ruby
# 設定ファイルの適切なところ
config.logger = ::Logger.new(STDOUT)

# controller 内など好きなところ
str = (1..820).map { |i| (i * 10).to_s.rjust(10, '.') }.join
Rails.logger.info(str)
```

アプリをターミナル上で実行したところ、ログは1行で出力されました。したがって Rails アプリは改行を入れていません。

```text:Rails&#x20のログ
I, [2023-10-19T21:34:28.201661 #85172]  INFO -- : Started GET "/" for 127.0.0.1 at 2023-10-19 21:34:28 +0900
I, [2023-10-19T21:34:28.206369 #85172]  INFO -- : Processing by MyController#index as */*
I, [2023-10-19T21:34:28.207268 #85172]  INFO -- : ........10........20........30（省略）......8190......8200
I, [2023-10-19T21:34:28.212750 #85172]  INFO -- :   Rendering text template
I, [2023-10-19T21:34:28.212872 #85172]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 3)
I, [2023-10-19T21:34:28.213109 #85172]  INFO -- : Completed 200 OK in 7ms (Views: 4.6ms | Allocations: 3721)
```

### Passenger のログを確認
同じサンプルアプリを Passenger 上で動かすため、 passenger-docker をベースにした Docker イメージをビルドして実行します。

ログを表示したところ改行されていて、**各行に Passenger によるプレフィックスが付いている**ことが確認できました（実際のアプリでは、プレフィックスがあると JSON にならないので消していました）。また、 Passenger のプレフィックスを除いた長さが最大 8192 バイトでした。

```text:Passenger&#x20のログ
App 171 output: I, [2023-10-19T12:35:11.601321 #171]  INFO -- : Started GET "/" for 172.17.0.1 at 2023-10-19 12:35:11 +0000
App 171 output: I, [2023-10-19T12:35:11.609502 #171]  INFO -- : Processing by MyController#index as */*
App 171 output: I, [2023-10-19T12:35:11.612206 #171]  INFO -- : ........10........20（省略）......8140....
App 171 output: ..8150......8160......8170......8180......8190......8200
App 171 output: I, [2023-10-19T12:35:11.615909 #171]  INFO -- :   Rendering text template
App 171 output: I, [2023-10-19T12:35:11.625906 #171]  INFO -- :   Rendered text template (Duration: 0.1ms | Allocations: 3)
App 171 output: I, [2023-10-19T12:35:11.626615 #171]  INFO -- : Completed 200 OK in 17ms (Views: 14.0ms | Allocations: 3702)
```

Rails はログを改行していなかったことと合わせると、 Passenger がログを改行したと考えるのが妥当です。

## コード調査
Passenger の処理で改行が加わる部分があるのか、ソースコードを調査しました。

Passenger がログにプレフィックスを付ける部分を手掛かりに grep したところ、出力処理に近いメソッドがすぐ見つかりました。内部ではバッファが動的に用意されているので、長いログも出力できそうです。
https://github.com/phusion/passenger/blob/release-6.0.15/src/cxx_supportlib/LoggingKit/Implementation.cpp

```cpp:src/cxx_supportlib/LoggingKit/Implementation.cpp
static void
realLogAppOutput(...)
{
	char *pos = buf;
	char *end = buf + bufSize;

	if (prefixLogs) {
		pos = appendData(pos, end, "App ");
		pos = appendData(pos, end, pidStr, pidStrLen);
		pos = appendData(pos, end, " ");
		pos = appendData(pos, end, channelName, channelNameLen);
		pos = appendData(pos, end, ": ");
	}
	pos = appendData(pos, end, message, messageLen);
	pos = appendData(pos, end, "\n");

	...
	writeExactWithoutOXT(targetFd, buf, pos - buf);
}

void
logAppOutput(...)
{
	...

	totalLen = (sizeof("App X Y: \n") - 2) + pidStrLen + channelName.size() + size;
	if (totalLen < 1024) {
		char buf[1024];
		realLogAppOutput(...);
	} else {
		DynamicBuffer buf(totalLen);
		realLogAppOutput(...);
	}
	if(fd > -1){close(fd);}
}
```

上記メソッド `logAppOutput()` の呼び出し元は2つありますが、どちらも基本構造は同じです。

* https://github.com/phusion/passenger/blob/release-6.0.15/src/agent/Core/SpawningKit/PipeWatcher.h
* https://github.com/phusion/passenger/blob/release-6.0.15/src/agent/Core/SpawningKit/Handshake/BackgroundIOCapturer.h

`buf` にログを読み込み、そこに含まれる `\n` を元に行を分割して出力しています。ただ、 **`char buf[1024 * 8]`** と定義されているため、長いログは分割して読み込むことになります。また、読み込んだ分は全て出力しきっていて、続きがある場合に連結している様子はありません。

```cpp:src/agent/Core/SpawningKit/PipeWatcher.h
		while (!boost::this_thread::interruption_requested()) {
			char buf[1024 * 8]; // (注) つまり 8192 バイト固定
			ssize_t ret;

			UPDATE_TRACE_POINT();
			ret = syscalls::read(fd, buf, sizeof(buf));
			...

				...
				split(StaticString(buf, ret2), '\n', lines);
				foreach (const StaticString line, lines) {
					printOrLogAppOutput(f, line); // (注) f == NULL のとき LoggingKit::logAppOutput() を呼び出す
				}
```

ここが原因だと断定するための調査まではできていないものの、改行回避のためにはログは Passenger を通してはいけないことになり、対応が大変そうです。

---

…と調べ終わった後、ふと GitHub 上の issue で `8KB` と検索したらまさに同じ話が見つかりました。

https://github.com/phusion/passenger/issues/2413

バッファサイズを設定可能にする pull request はマージ済みで、 Passenger 6.0.17 で[リリースされています](https://github.com/phusion/passenger/releases/tag/release-6.0.17)。

> * Adds support for a `PASSENGER_MAX_LOG_LINE_LENGTH_BYTES` environment variable. The default length remains at 8KB. Closes GH-2413.

passenger-docker でも提供されているので、ベースイメージを更新してこの環境変数を設定すれば良さそうです。（だからといって 1MB など際限なく長いログを出していいかは疑問ですが）