WordPressで構築されたサイトを、ぼーっと巡回していたときのことです。
運用から引き継いだので、WebInspector(DeveloperTools)を開きながら、どんな構成なんだろうなと思いながら見ていたところ、あるアーカイブページから、HTTPステータスコード500が返ってきました。
ページは正常に表示されている(ように見える)のに、どういうことだろうと思い、再度更新してみると今度は通常のHTTPステータスコード200が返ってきました。
同じアーカイブの他のページを見ると、たしかに、たまに500が返ってきます。
不思議に思いましたが、他にクリティカルなものがそれはたくさんありましたので、ページは特に何事もなく表示されているし、後ほど対応しようということにしました。
そして、数日経ったあるとき、WebマスターツールからInternalServerエラーが急激に増加していますという警告が届きました。
内容を確認してみると、先ほどのアーカイブページでした。
そもそもの認識どおり、ときおり500を返却していたのでこれまでエラーの数は0ではありませんでした。ただ、たしかにクロールエラー(ServerError)が数倍に急増していました。なぜでしょうか?
調査開始
まずは、該当のページの出力内容を確認しました。
HTMLとしては、ほぼ問題ないように思いましたが、一点奇妙な点がありました。
このサイトは、キャッシュ機構にQuickCacheプラグインを利用しているのですが、キャッシュされた旨のコメントがあるべきところにありません。
あるべきところとは、本来HTMLの最後なのですが、このページに至っては、最後より少し上の位置にありました。
なぜかと思って見てみると、なるほど、フッターの一部が出力されていませんでした。不自然な位置で出力が止まってしまっています。キャッシュされた旨のコメントは、そこに出力されていました。
フッターの一部とはいっても、目に見える要素は全て出力済みで、処理が止まっていたのは、その後に続くインラインスクリプトの部分でしたから、ページとしての見た目には影響がなかった様です。
そこで、開発環境でデバッグしてみると、この部分でFatalErrorが発生していました。どうやら500の原因はここみたいです。
ただ、開発環境では、HTTPステータスが500になることはありませんでした。
というのも、既に必ずヘッダーが出力されていたからです。
では、HTTPステータスが500になるのはどういう状況でしょうか?
そこで、本番環境に合わせるべく、開発環境では無効にしていたQuickCacheプラグインを有効化すると、
たしかに、HTTPステータスが500を返しました。しかし、もう一度確認すると、今度はHTTPステータス200です。
これでわかりました。アクセス時にキャッシュが作成された場合は500を返すのではないかと。
そこで、試してみました。
キャッシュをクリアしてアクセスすると、500。キャッシュがある状態でアクセスすると200。
どうやら間違いなさそうです。
そこで、QuickCacheがキャッシュを作成するフローを確認しました。
QuickCacheのフロー
WordPressへのアクセスに対して、まず、それがキャッシュを許可するものかどうかを調べます。
許可されている場合、キャッシュ化されたファイルが既にあるか、またそれが有効なキャッシュかを調べます。
該当するファイルがあれば、キャッシュファイルを出力し、WordPressの処理が終了します。
ここで、もし有効なキャッシュが無かった場合、キャッシュファイルの作成を開始します。
QuickCacheがob_start();
でバッファリングを開始します。
そして、WordPress本来の処理が行われ、該当のページの表示がバッファリングされていきます。
最終的に、それがキャッシュファイルに書き込まれ、同時に、レスポンスとして出力されます。
前述の事象では、まさにここが問題でした。
fatal errorが出力するサーバーエラーのヘッダーが、バッファリングされずに先に出力されてしまっていたのです。
それぞれを整理すると下記の様な処理が行われていました。
キャッシュ未使用時
200 -> 500(バッファリングされないのでコード順で処理)
キャッシュ生成時
500 -> 200(コードはバッファリングされていのに、fatal errorが先にヘッダーを出力)
キャッシュ読込時
200のみ (出力されたHTMLを表示するだけなのでfatal errorは発生しない)
クロールエラー急増の原因
これは推測になってしまうのですが、クロールされる直前に記事更新等でQuickCacheのキャッシュがクリアされたのではないかと思われます。これまでも同じページへのクロールエラーが0ではなかった点、および、そもそも頻繁なアクセスがあるページではなかったので、タイミングの問題かと。
対処方法
エラーにならないコードを書きましょう!
まとめ
WordPressに限らない話と思いますが、意図せずにHTTPステータスコード500が検出されるようになったら、バッファリングを行ってる箇所を探してみる、のもいいかもしれませんね。