最近nginx+php-fpmを使い始めました。初心者です。
開発環境をvagrantで構築して1つのマシン上で完結させているのですが、どうにも上手く動いてくれなかったときに確認したことです。
実行してもPHPだけ動いてくれない
症状は厄介なもので、HTMLファイルなどは普通に返してくれるのにPHPを実行させようとするとそこで応答が返ってこない。
nginxのアクセスログには499エラーが記録されたりされなかったりしており、php-fpmのサービスをrestartするとそこで502エラーとなることからphp-fpmに処理は渡っていると推測できましたが、
<?php phpinfo();
すら応答がないのでちょっとよくわからない。
つまり状況としては、php-fpmがフリーズしているように見えていました。
/var/log/php-fpm/error.logを確認してみても特に何も出力されていない状況。
XDebugが邪魔をしていた
結局のところ原因は、IntelliJで設定してたXDebugが邪魔をしていたようでした。
起動していたIntelliJを全て終了させてみたところ、無事動作しました…
これがブレークポイントを仕込んでいたのを忘れていたとかでしたら間抜けな話で済むのですが、全然関係ないところでDocumentRootを切り直し、新しく作ったphpinfoだけのスクリプトでもストップして、IDE側に応答が返ってきたわけでもないので、デバッグ用の仕組みがおかしな動作をしていたのではと思います。
php-fpmとnginxの接続はUNIXソケットで行っていましたがデフォルトポートが9000だったので念のためポート周りを調べていたところ、vagrant側で
# netstat -an | grep 9000 tcp 0 0 192.168.1.10:49593 192.168.1.1:9000 ESTABLISHED
と、ホストOS側(192.168.1.1)の9000ポートに接続しにいっているものがありまして、ホストOS側でlsofしてみたところ、
$ lsof -i:9000 22:31: COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME idea 712 myuser 16u IPv4 xxxx 0t0 TCP 192.168.1.1:cslistener->guest1.hoge.com:49519 (ESTABLISHED) idea 712 myuser 29u IPv4 xxxx 0t0 TCP *:cslistener (LISTEN) idea 712 myuser 36u IPv4 xxxx 0t0 TCP 192.168.1.1:cslistener->guest1.hoge.com:49521 (ESTABLISHED) idea 712 myuser 38u IPv4 xxxx 0t0 TCP 192.168.1.1:cslistener->guest1.hoge.com:49524 (ESTABLISHED) idea 712 myuser 39u IPv4 xxxx 0t0 TCP 192.168.1.1:cslistener->guest1.hoge.com:49526 (ESTABLISHED)
とLISTENしているものと、そこからゲストOSにセッションを張っているものがいました。
でもこちらでphp-fpmを動作させているわけないし、COMMANDはideaだし…と思ったところでIntelliJのXDebugがポート9000だったことを思い出し、IntelliJを終了させてみたところ無事動きました。
ESTABLISHEDな接続がなぜか何本も出来ていたあたり、やはり何かしらおかしくなっていたのではと思います。
Macは普段スリープさせてるし再起動したとしても開いていたアプリは復帰してくるので、ポート番号がたまたま9000で被っていなければ気がつかなかったかもしれません…
xdebugの設定
このゲストOSの開発環境はコンソールからテストを実行する絡みもあって、xdebugの接続がすべてホストOSに行くように、
xdebug.remote_host=192.168.1.1 xdebug.remote_connect_back=0
を設定していました。
このため(おそらく開始直後に)IDEのほうに処理が流れていき、そこで何か上手くいかず、結果としてストップしてしまっていたのかと思います。
同じような現象になってしまった場合はIDEを終了させてみたり、このあたりの設定を見直してみると良いかもしれません。
全く関係ないと思っていたスクリプトも無反応に
この類似事例で、Dockerでコンテナ分けて開発していた全く別のプロジェクトもフリーズすることがありました。xdebugの送信先が同じホストになっていたため仕組みとしては一緒ですが、さらに気づくのが難しかったです。
このときは幸いにしてログにタイムアウトが残り、nginxが504でエラーとなっていたのでまだ手がかりがありました。
nginxのerror.logとphp-fpmのerror.logには次のように記録されていました。
・nginxのerror.log
[error] 6#6: *13 upstream timed out (110: Connection timed out) while reading response header from upstream, client: xxx.xxx.xxx.xxx, server: sample.scriptlife.jp, request: "GET / HTTP/1.1", upstream: "fastcgi://yyy.yyy.yyy.yyy:9000", host: "sample.scriptlife.jp"
・php-fpmのerror.log
ERROR: failed to ptrace(ATTACH) child 51: Operation not permitted (1)
WARNING: [pool www] child 51, script /path/to/index.php' (request: "GET /index.php") executing too slow (1.024234 sec), logging
WARNING: [pool www] child 25, script '/path/to/index.php' (request: "GET /index.php") execution timed out (300.188529 sec), terminating
WARNING: [pool www] child 25 exited on signal 15 (SIGTERM) after 495.279129 seconds from start
NOTICE: [pool www] child 69 started
300秒超えているものは、たぶん何度か試していたうちの一つが遅れてタイムアウトしているのではと思います。
意味不明なタイムアウトをしていたらとりあえずXDebugとホスト側のIntelliJ(または受信しているIDEなど)を確認してみると解決するかもしれません…