Apache2.4+PHP-FPM環境でのproxy_fcgi:error (22)Invalid argumentについて

Question

以下の環境でWebアプリケーションを稼働させているのですが、ちょくちょくエラーログが記録されており、内容を調べてもちょっとわからないところがあったので、質問させていただきます。

■環境
・CentOS 7
・Apache 2.4.6
・PHP7.0.3 （PHP-FPMで実行）

PHP-FPMを実行するために、Apacheには以下の設定をしています。

<VirtualHost *:80>
  ServerName hoge.jp
  DocumentRoot /var/www/html

    # error settings.
    # ProxyPass /error !
    ProxyErrorOverride On
    ErrorDocument 503 /error/503.html
    ErrorDocument 404 /error/404.html
    
    #php-fpm settings.
    #phpMyAdmin用
    ProxyPassMatch ^/phpmyadmin/(.*\.php(/.*)?)$ fcgi://127.0.0.1:9000/usr/share/phpMyAdmin/$1
    ProxyPassMatch ^/phpmyadmin/(.*\.php(/.*)?)$ fcgi://127.0.0.1:9000/usr/share/phpMyAdmin$1index.php
    #ドキュメントルート以下のPHP用
    ProxyPassMatch ^(.*\.php(/.*)?)$ fcgi://127.0.0.1:9000/var/www/html/$1
    ProxyTimeout 60
    DirectoryIndex index.php

</VirtualHost>

アプリケーションの内容は、PHPで画像を編集するものなので、現状は一見問題無さそうに動いています。
ユーザー問い合わせも特に無い状況ですが、エラーログの記録があるので、気になって調査中です。

エラーログの内容は以下です。

[Mon Mar 14 00:46:43.894126 2016] [proxy_fcgi:error] [pid 4626:tid 139748445882112] [client **.***.***.***:12610] AH01068: Got bogus version 122, referer: http://hoge.jp/
[Mon Mar 14 00:46:43.894217 2016] [proxy_fcgi:error] [pid 4626:tid 139748445882112] (22)Invalid argument: [client **.***.***.***:12610] AH01075: Error dispatching request to :, referer: http://hoge.jp/
[Mon Mar 14 00:46:57.008903 2016] [proxy_fcgi:error] [pid 4626:tid 139748319991552] [client **.***.**.**:36604] AH01068: Got bogus version 253, referer: http://hoge.jp/
[Mon Mar 14 00:46:57.008997 2016] [proxy_fcgi:error] [pid 4626:tid 139748319991552] (22)Invalid argument: [client **.***.**.**:36604] AH01075: Error dispatching request to :, referer: http://hoge.jp/
[Mon Mar 14 00:47:11.619729 2016] [proxy_fcgi:error] [pid 4626:tid 139748672485120] [client **.***.***.***:12630] AH01068: Got bogus version 122, referer: http://hoge.jp/
[Mon Mar 14 00:47:11.619848 2016] [proxy_fcgi:error] [pid 4626:tid 139748672485120] (22)Invalid argument: [client **.***.***.***:12630] AH01075: Error dispatching request to :, referer: http://hoge.jp/
[Mon Mar 14 00:47:21.925547 2016] [proxy_fcgi:error] [pid 4626:tid 139747858392832] [client **.***.**.**:36653] AH01068: Got bogus version 253, referer: http://hoge.jp/
[Mon Mar 14 00:47:21.925648 2016] [proxy_fcgi:error] [pid 4626:tid 139747858392832] (22)Invalid argument: [client **.***.**.**:36653] AH01075: Error dispatching request to :, referer: http://hoge.jp/

常に出るわけではなく、アクセスの多い時によく出ているような印象です。
アクセスが少ない時は1時間に1件ある程度だったりするので、何らかの条件をもったリクエストに対して発生しているような気がしますが、Apacheのaccesslogの方で同時刻帯のログを調べても、502や503エラーなどは出ていないので、原因は不明のままです。

エラーログのキーワードを検索したところ、下記のような記事を見つけました。

http://serverfault.com/questions/708438/what-is-this-error-in-apache-error-log

http://stackoverflow.com/questions/29089683/virtualhost-on-apache-2-4-with-php-fpm-getting-proxy-fcgierror

しかし、いずれも解決に至っていないようです。

こういったエラーの原因について、どなたかご存知でしたら、ご回答いただけますと幸いです。

Answer 1

Red hatのナレッジに情報があります。

https://access.redhat.com/solutions/1311233

一番簡単な解決策にはこう書いてありましたので、試してみてはいかがでしょうか。

「The simplest solution is simply to add "disablereuse=on" to the ProxyPassMatch line to ensure the connecting pipe is torn down each time.」

Comments

[snic518]

ご回答ありがとうございます。
すみません、Red Hatのアカウント作ったのですが、ナレッジベースが見れなかったので念のため…。

ProxyPassMatch ^(.*\.php(/.*)?)$ fcgi://127.0.0.1:9000/var/www/html/$1 disablereuse=on

こういうことですね。
試してみようと思います。

[Tira]

はい。
そういう事だと思います。
ナレッジが見られないとの事でしたので、原因について軽く書きますと、
どうやらApacheとバックエンドとの間のセッションが再利用されており、
あるリクエストの後、次のリクエストを処理しようとした際に部分的に次のリクエストのある一部分が読み込まれ受信したデータをプロトコルバージョンとして読み込んだ結果、このエラーが発生する事がある様です。
なので、このセッション再利用を辞めると発生しなくなる、という事みたいですね。

お役に立ったなら幸いです。
お試し下さい。

[snic518]

ご回答ありがとうございました。
上記のように設定し、Apacheを再起動し様子を見てみました。
しかし、同様の(22)Invalid argumentエラーは再度発生してしまいました。

この関連パラメータを調べていてひとつ気になったのですが、
元記事に書き忘れてますがApacheの設定でKeepAliveがOnになっています。
ですので、

http://hogem.hatenablog.com/entry/20100909/1283961055

こちらの記事にあるように、

SetEnv proxy-nokeepalive 1

も合わせて設定する必要がある、と思ったので、今度はこちらを試してみようと思います。
ご意見あれば、いただけますと幸いです。

[Tira]

まだダメですか。
バックエンド向けのKeepAliveをOFFにするのは、方向性として近そうですね。
続報お待ちしております。

[snic518]

SetEnv force-proxy-request-1.0 1
SetEnv proxy-nokeepalive 1

こちらをProxyPassMatch の次に追記し、Apache再起動して様子を見てみました。

するとやはり同様のエラーログが出ているのですが、変更前よりは多少頻度が減ったような印象があります。

※GoogleAnalyticsのセッション数が500/h程度のアクセスあたり、1～2回発生していたのが半分程度になりました。
　時間的なサンプルはまだ少ないのでなんとも言えないですが…。

なお、この現象を調査中に自分のIPでも同じエラーログを発生させたことを確認出来たのですが、おそらく、リクエスト直後に一旦ブラウザバックする等の若干イレギュラーな操作を行った時に発生したように思います。再現性はありませんでしたが…。

通常操作において動作に問題無いのは確かなようなので、この頻度であれば許容していっても良いのかもしれないですね。

[Tira]

続報ありがとうございます。
頻度は減ったがまだ出る、という事はまだ別な要因があるのかもしれませんね。

https://bz.apache.org/bugzilla/show_bug.cgi?id=57398

こちらを見るとApache:2.4.10でもバグジラが切られていて未解決なので、
バージョンアップで出力されなくなる様な問題でも無さそうですね・・。

現状オンラインリクエストへの影響が無いのであれば、静観、許容としても良いかも知れませんね。

[snic518]

色々とアドバイスありがとうございました。
いただいた記事も、参考にさせていただきます。

実際のところ、まったく影響が無いのかについては不明のままでありますので、
PHP-FPMではなくApacheモジュールに変えることも視野に入れようと思います。