はじめに

NginxとPHP-FPMをsupervisorで起動したDockerコンテナ内にLaravel環境を作っていました。

無事Laravelのwelcomeページが表示できるようになったものの、
docker logsを見てみるとアクセスログがおかしいことに気付きました。

172.17.0.1 - - [26/Mar/2022:15:27:56 +0900] "GET / HTTP/1.1" 200 17606 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.82 Safari/537.36"
- -  26/Mar/2022:15:27:56 +0900 "GET /index.php" 200

ん？この下のログは何？

何故かアクセスログが二重に出力されていたのです。
しかもフォーマットが違う。

ということで出力されるログを1つにしようとしたのですが、
結局解決までに3時間近く掛かりました。

なかなかに心が疲弊しました。

心を落ち着かせるためにも記事として残しておきます。

原因

で結局何が原因だったかというと、
PHP-FPM側のアクセスログの設定でした！

はい、最初に紹介した2つ目に出ていたログというのは
PHP-FPMのアクセスログだったんですね。

そもそも今回のDockerコンテナのベースイメージはphp:7.4-fpm-alpineを使っていたのですが
PHP-FPM側のログの制御というのは/usr/local/etc/php-fpm.d/docker.conf内でやっています。

でそこにあったんですね。
PHP-FPM側のアクセスログの設定が！

[www]
; if we send this to /proc/self/fd/1, it never appears
access.log = /proc/self/fd/2

はい。

そしてご丁寧にコメントで「/proc/self/fd/1に送ったら出力されなくなるよ」と言ってくれているので
/proc/self/fd/1に変更したところ、無事出力されなくなりました。

こんなことかよ、と思いました。

ハマった最大の原因

振り返ってみると私が盛大にハマった最大の原因は、
アクセスログなんだからNginxが出力しているんだろうという思い込みでした。

その思い込みがあったため、Nginxのaccess_log周りの設定に問題があると考え、
そこばかりイジって無駄に何時間も浪費してしまいました。

ただその過程でaccess_log周りの設定に関して色々勉強できたので
良かった部分もありましたけどね！

あとがき

思い込みって怖いです。
「これNginxの問題ではないのでは？」ともっと早く気付けたらと非常に悔やまれます。

何時間も同じところに詰まり続けたら
何か根本的に勘違いしているんじゃないかと疑った方がいいですね！

参考サイト

Docker + Nginx + Laravel(PHP-FPM)な環境のログを整理する