第123回PHP勉強会@東京での新倉 涼太さんのLT「コンテナのログについて」で話題になったnginxとphp-fpmでのエラーログの扱いについて気になったので調べて見ました。かいつまんでいうとdockerでnginxコンテナとphp-fpmコンテナが同じエラーログを重複して出すのをなんとかできないかという話でした。私もそういえば重複して無駄だなと昔一瞬思った気がしますけどそのまま放置してたので。
FastCGIの仕様
FastCGIはコネクション1本でいろんなデータを混ぜて送れるように中身はレコードに分割されていて、レコードのtypeがFCGI_STDOUT(=6)だとブラウザに送るbody, FCGI_STDERR(=7)だとエラー出力みたいな感じになっています。
https://github.com/FastCGI-Archives/fastcgi-archives.github.io/blob/master/FastCGI_Specification.md の8章に例があるので雰囲気をつかむのにはいいでしょう。
nginx
fastcgiの処理はsrc/http/modules/ngx_http_fastcgi_module.cで行われています。ngx_http_fastcgi_process_headerという関数の if (f->type == NGX_HTTP_FASTCGI_STDERR) {で開始するあたりがその処理で、ログ出力に関してざっくり言うと、受け取った内容を行に分割しておなじみのFastCGI sent in stderr:を頭に付けてerrレベルでログに出力します。特に分岐などないので、基本的に送られてきたものはそのまま出ます。出したくなければfastcgiサーバ側が送らないようにするか、(他のログも巻き添えになることを覚悟して)errレベルをログに出力しない設定にするしかないでしょう。
php-fpm
php-fpmでFCGI_STDERRを送ってるところを探すとsapi/fpm/fpm/fpm_main.cの中にあるsapi_cgi_log_fastcgiが割とすぐにみつかります。
/* {{{ sapi_cgi_log_fastcgi
*
* Ignore level, we want to send all messages through fastcgi
*/
void sapi_cgi_log_fastcgi(int level, char *message, size_t len)
{
fcgi_request *request = (fcgi_request*) SG(server_context);
/* ensure we want:
* - to log (fastcgi.logging in php.ini)
* - we are currently dealing with a request
* - the message is not empty
*/
if (CGIG(fcgi_logging) && request && message && len > 0) {
ssize_t ret;
char *buf = malloc(len + 2);
memcpy(buf, message, len);
memcpy(buf + len, "\n", sizeof("\n"));
ret = fcgi_write(request, FCGI_STDERR, buf, len + 1);
free(buf);
if (ret < 0) {
php_handle_aborted_connection();
}
}
}
/* }}} */
fcgi_loggingという設定で出力するかどうかを制御できるように見えます。
STD_PHP_INI_ENTRY("fastcgi.logging", "1", PHP_INI_SYSTEM, OnUpdateBool, fcgi_logging, php_cgi_globals_struct, php_cgi_globals)
設定名はfastcgi.loggingというようです。
マニュアルの説明( http://php.net/manual/ja/ini.core.php#ini.fastcgi.logging )は「FastCGI 使用中の SAPI ロギングを有効にします。」とあります。「SAPIロギング」って何なのって感じですが、SAPIというのがweb serverとの間のAPI(この場合はFastCGI)で、それ経由でログを送るって意味なんでしょうか。たぶん調べないでこの説明だけ見ても私にはなんのことやらだったでしょう。
実験
実験するためのdockerの設定を作成しました。
適当なブラウザで http://localhost:21080/foo.php にアクセスするとエラーを出力するようになってます。
<?php
ini_set('error_reporting', E_ALL);
error_log('foo error!!');
echo $x['foo'];
file_put_contents('php://stderr', "output to stderr!!\n");
phpinfo();
php.iniのfastcgi.loggingの値によってnginx側にphpのエラーログが出たり出なかったりするのが確かめられると思います。
fastcgi.logging = 0の場合:
% docker-compose up
Recreating phpfpmlog_fpm_1 ... done
Recreating phpfpmlog_nginx_1 ... done
Attaching to phpfpmlog_fpm_1, phpfpmlog_nginx_1
fpm_1 | [01-Mar-2018 04:27:06] NOTICE: fpm is running, pid 1
fpm_1 | [01-Mar-2018 04:27:06] NOTICE: ready to handle connections
fpm_1 | [01-Mar-2018 04:27:13] WARNING: [pool www] child 6 said into stderr: "NOTICE: PHP message: foo error!!"
fpm_1 | [01-Mar-2018 04:27:13] WARNING: [pool www] child 6 said into stderr: "NOTICE: PHP message: PHP Notice: Undefined variable: x in /var/www/html/foo.php on line 5"
fpm_1 | [01-Mar-2018 04:27:13] WARNING: [pool www] child 6 said into stderr: "output to stderr!!"
fpm_1 | 172.20.0.3 - 01/Mar/2018:04:27:13 +0000 "GET /foo.php" 200
nginx_1 | 172.20.0.1 - - [01/Mar/2018:04:27:13 +0000] "GET /foo.php HTTP/1.1" 200 85316 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/604.5.6 (KHTML, like Gecko) Version/11.0.3 Safari/604.5.6" "-"
fastcgi.logging = 1の場合:
% docker-compose up
Starting phpfpmlog_fpm_1 ... done
Starting phpfpmlog_nginx_1 ... done
Attaching to phpfpmlog_fpm_1, phpfpmlog_nginx_1
fpm_1 | [01-Mar-2018 04:28:52] NOTICE: fpm is running, pid 1
fpm_1 | [01-Mar-2018 04:28:52] NOTICE: ready to handle connections
fpm_1 | [01-Mar-2018 04:28:58] WARNING: [pool www] child 5 said into stderr: "NOTICE: PHP message: foo error!!"
fpm_1 | [01-Mar-2018 04:28:58] WARNING: [pool www] child 5 said into stderr: "NOTICE: PHP message: PHP Notice: Undefined variable: x in /var/www/html/foo.php on line 5"
fpm_1 | [01-Mar-2018 04:28:58] WARNING: [pool www] child 5 said into stderr: "output to stderr!!"
nginx_1 | 2018/03/01 04:28:58 [error] 5#5: *1 FastCGI sent in stderr: "PHP message: foo error!!
nginx_1 | PHP message: PHP Notice: Undefined variable: x in /var/www/html/foo.php on line 5" while reading response header from upstream, client: 172.20.0.1, server: localhost, request: "GET /foo.php HTTP/1.1", upstream: "fastcgi://172.20.0.2:9000", host: "localhost:21080"
fpm_1 | 172.20.0.3 - 01/Mar/2018:04:28:58 +0000 "GET /foo.php" 200
nginx_1 | 172.20.0.1 - - [01/Mar/2018:04:28:58 +0000] "GET /foo.php HTTP/1.1" 200 85318 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/604.5.6 (KHTML, like Gecko) Version/11.0.3 Safari/604.5.6" "-"
余談
これでnginx側にfpmのエラーログが重複して出なくなったのはいいけど、いちいち頭に「WARNING: [pool www] child 5 said into stderr:」ってついてるの邪魔くさくないですか?
で、調べて見たのですがこれ Logs to stdout get prefixed with warning in php-fpm image #207 とか#71880 Optionally disable warnings when writing to STDOUTで議論されている問題のようです。かなり前に提起されてるのにいまだに解決してないようです。頭に邪魔なのがつくのは我慢すればいいとも言えますが、行が長いとお尻も切れるらしいのでこっちは問題だよな。
ログをfifoに出してコンテナの出力はそいつのtail -fにするみたいな回避策も紹介されています。
(2019-10-07追記)
7.3.0から接頭辞をつけなくする設定が追加されたそうです。