sunnyone.org
発端
とあるPHPアプリケーションがエラーログをPHP標準関数error_log()で吐く。それをフィルタしたくなったのだが、error_log()にはたいしたフックポイントもなく、アプリケーション自体には手を入れたくないので、とりあえずsyslogで受けてSyslogサーバーがなんとかするのがよいかと思って「error_log」の設定を「syslog」にしてみると、なぜかこんな感じに……Feb 7 22:02:36 phptest ool www: LOG CONTENT
……この「ool www」は一体なんなんだ？ Out-of-L...うーん。ここの文字列だけなら実害はないが、なんでこんなことになっているのかわからないので調べることにした。
テストファイル
当該のPHPアプリケーションは置いといて、1ファイルでも再現するので、以下のPHPプログラムでテストすることにする。<?php error_log("ERRORTEST"); ?>
環境はUbuntu 14.04にnginx + php5-fpm。設定値「error_log」を「syslog」にしておく。あまりバージョンに拘っていないので、リンクが適当だったりするが気になるかたは必要なバージョンのソースを見に行ってほしい。
ソースを追う
error_log()関数の流れ
くだんのerror_log()関数をPHPから呼び出すと、こんな感じで動く。まず、error_logのPHP_FUNCTIONの記述がext/standard/basic_functions.cにある。ここが実体である_php_error_log_ex()を呼び出す。
ext/standard/basic_functions.cの_php_error_log_ex()は、switchで引数に応じたログ出力（メールなど）を行う。今回のmessageのみの呼び出しではdefault: にたどり着き、php_log_err()を呼び出す。
php_log_err()は、main/main.cにあり、ここで「error_log」変数のチェックを行い、値が「syslog」のときはphp_syslog()関数でsyslogに出力している。
if (!strcmp(PG(error_log), "syslog")) {
php_syslog(LOG_NOTICE, "%s", log_message);
PG(in_error_log) = 0;
return;
}
基本的にメッセージを引き回しているだけで、ここまでに変わった文字列処理は見受けられない。
php_syslog()関数とは
であればポイントはphp_syslog()であろうと、php_syslog()の定義をphp_syslog.hに見つけるも、こうなっていた。なんとphp_syslog()はsyslog()であった。つまり、PHP内で何か特別な処理をすることなく、そのままsyslog()関数にメッセージを投げているだけである。
syslog関数の使い方
こうなってくるとsyslog(3)が大事になる。manがあり、日本語が古くないようなので日本語のsyslog(3)を見てみる。プロトタイプとしては、こうなっているようだ。
#include <syslog.h> void openlog(const char *ident, int option, int facility); void syslog(int priority, const char *format, ...); void closelog(void);
呼び出しとあわせると、priorityがLOG_NOTICEで、formatが"%s"、%s部分としてlog_messageが渡ることになる。
説明を読むと
ident で指定した文字列は各メッセージの前に付与される。とあるので「ool www」の部分はidentのようだ。
処理の中でとくにopenlog()する処理は見受けられなかったので
openlog() は必須ではなく、必要に応じて syslog() から呼び出される。 syslog() が呼び出した場合、 ident のデフォルト値は NULL になる。の部分に該当し、
通常は ident にはプログラム名が設定される。 ident が NULL の場合、プログラムが ident として使用されるとあるので「ool www」はプログラム名のようだ。しかし「ool www」なんてプログラムはいないぞ？
syslog()関数の実装
こうなると、identがNULLだったときのopenlog()の動きを知りたくなる。そこでglibcを見たところ、openlog()の実体はmisc/syslog.cにある。openlog()は内部のopenlog_internal()を呼び、ここでidentはLogTag変数に代入される。
LogTagがNULLのときの処理を探してみると、syslog()のログ処理の実体である__vsyslog_chk()に以下の記述があった。
if (LogTag == NULL)
LogTag = __progname;
__prognameは何かと見ると、頭のほうでexternで宣言されていた。
extern char *__progname; /* Program name, from crt0. */だいぶあやしい。
「__progname」とは
で、誰が__prognameをセットしているのかと探してみると「misc/init-misc.c」にあった。void
__init_misc (int argc, char **argv, char **envp)
{
if (argv && argv[0])
{
char *p = strrchr (argv[0], '/');
if (p == NULL)
__progname = argv[0];
else
__progname = p + 1;
__progname_full = argv[0];
}
}
__prognameは「argv[0]の最後の'/'より後」のようだ。なるほどargv[0]の役目を考えると妥当そうに見える。__progname_fullとしてargv[0]も保持されている。php-fpmのargv[0]ってなんだっけ？
phpが動作するのは、php-fpmプロセス。そういえばphp-fpmは独自設定した文字列がpsで見えてたよなと見てみると、こうなっている。$ ps -ef | grep '[p]hp-fpm' root 2664 1 0 22:02 ? 00:00:00 php-fpm: master process (/etc/php5/fpm/php-fpm.conf) www-data 2666 2664 0 22:02 ? 00:00:00 php-fpm: pool www www-data 2667 2664 0 22:02 ? 00:00:00 php-fpm: pool www
php-fpmは明らかにargv[0]を書き換えている。勘のいい人ならもうお分かりだろう。一応検証するために、PHPを適当に展開してfpm.cのfpm_init()の頭と末尾（argvが書き換わる前と後）に以下のようにログを仕込んでみる（ヘッダやexternは適宜挿入）と...
zlog(ZLOG_NOTICE, "argv[0]: %s", argv[0]);
zlog(ZLOG_NOTICE, "__progname: %s", __progname); zlog(ZLOG_NOTICE, "__progname_full: %s", __progname_full);
こんな風になる。
$ sudo ./sapi/fpm/php-fpm -F -y /etc/php5/fpm/php-fpm.conf [08-Feb-2016 00:25:23] NOTICE: argv[0]: ./sapi/fpm/php-fpm [08-Feb-2016 00:25:23] NOTICE: fpm is running, pid 24381 [08-Feb-2016 00:25:23] NOTICE: __progname: ster process (/etc/php5/fpm/php-fpm.conf) [08-Feb-2016 00:25:23] NOTICE: __progname_full: php-fpm: master process (/etc/php5/fpm/php-fpm.conf)もう少しわかりやすくすると、こう。
そう、元々あった最後の/までの文字数分、新しい文字列の開始からスキップされている。ログ出力がだるいので例ではmaster processになっているが、pool wwwでどうなるかを想像するのはたやすいと思う。
結論：syslog tagに使われる__prognameを、プログラムパスであるargv[0]からディレクトリ部分を取り除いた文字列へのポインタとしてlibcが保存したあと、php-fpmがargv[0]を書き換えたため、謎の文字列「ool www」が生まれた。
一応Bug reportは作っておいた。PHPが対処すべき問題のように感じるけど、libcが文字列をコピーしておかないのが悪いって言われるとそうすかって感じなので、正直期待できない：https://bugs.php.net/bug.php?id=71544
回避策：identに妥当な値を設定するには？
暗黙のopenlog()をさせなければいい。つまり、期待のプログラムが動く前にopenlog()すればよい。具体的には、以下のようなファイルを例えば/etc/php5/fpm/fixsyslog.phpと置いて……
php.iniのauto_prepend_fileで参照する。
auto_prepend_file = /etc/php5/fpm/fixsyslog.php
これで常にopenlog()が呼ばれるので現象は起こらない。
感想
原因に関しては、ソースを追うことですっきりさせることができた。オープンソースのありがたみって、やっぱりこういうところにあると思う。解決策は、もやもやが残るままだけど…おまけ：php-fpmはどのようにargv[0]を書き換えているか？
php-fpmは見ての通りargv[0]を書き換えるのだけど、argvを全部足しても期待の文字数に足りないなんてこともあるはず。そんなときの処理がfpm_env.cに書かれていた。ざっくり言うと「environがargvとメモリ空間上に連続で置いてあるから、一応確認しつつenvironにどいてもらって、そこをargv[0]として使いましょう」である。グロい！コメントによると、nginxやpureftpdもそうしているらしい。
この記事も最後なので該当コードを貼り付けておく。
