とある技術屋の戯言

現象を説明するとたったこれだけなんですが、原因調査と解決にえらい苦労したのでその記録

Apacheのアクセスログでレスポンスコードが1になっている妙なレコードがたくさんあるのを見つけたのが発端。まず、アプリの側でリクエストとレスポンスをログに吐いてみたら、こっちのログでは304になっているのがApache側では1になっているのが分かったので、実際に304が返るはずのリクエストを投げてみると、"500 Internal Server Error"という無情なメッセージが。server.plではきちんと304が返ってくるので、気づいてませんでした。

これでmod_perl(というかCatalyst::Engine::Apache)を使ったときの問題であることははっきりしたのですが、なにせmod_perlがよく分かってないので調べるのが大変。304を返すときに余計なデータを付けてるとこうなるのか、はたまた足りないからこうなっているのか…というあたりで試行錯誤してたんですが、さっぱり進展がありません。

結局、mod_perlの勉強がてら簡単なmod_perlのハンドラを作ってさらに試行錯誤してみることに。試してる途中のコードはこんな感じ。

package Hello;

use strict;
use warnings;

use Apache2::RequestRec;
use Apache2::RequestIO;
use Apache2::Response;
use Apache2::Const -compile => 'OK';

sub handler : method {
    my ($class, $r) = @_;
    $r->content_type('text/plain');
    $r->set_content_length(2);

    $r->print('no');
    if($r->headers_in->{'If-Modified-Since'})
    {
        $r->status(304);
    }
    $r->set_last_modified(1000000000);
    return Apache2::Const::OK;
}

1;

ところが、足したり引いたりしてもどうやっても再現できません。この線はあきらめて、またwebをさまよっていたら、naoyaのはてなダイアリー - mod_perl の Apache::OKという記事を発見。実は前にも見てたのにそのときはヒントだとは気づきませんでした。ポイントはコメントにある、$c->res->statusで設定した値がCatalyst::Engine::Apacheの中で$r->statusに渡されて、ApacheにはApache::OK(=0)が返る、という所。Catalyst/Engine/Apache.pmを見ると、166行目あたりにこんなコードがあります。

# The trick with Apache is to set the status code in $apache->status but
# always return the OK constant back to Apache from the handler.
$self->apache->status( $c->response->status );
$c->response->status( $self->return || $self->ok_constant );

なるほど、$c->res->statusが $self->apache->status*1に渡されてます。で、その後で$c->res->statusに設定された$self->ok_constant*2はどこに行ってしまうのか、というのを追跡開始。

まず、さっき作ったmod_perlのテストで、sub handler : method てのが重要だろうというのは想像できたので、これに相当する物がCatalystのどこかにあるはずですので探してみると、Catalyst.pmの1940行目にありました。

*handler = sub  : method {
    shift->handle_request(@_);
};

sub handle_requestを覗いてみると、$status = $c->finalizeとreturn $statusという行があります。デバッグプリントを仕掛けて$statusの値をみると、アプリ側で指定した$c->res->statusが200のときは、server.plだと200、mod_perlだと0ですが、$c->res->statusを304にすると1が返ってきます。今度は、sub finalizeの中にデバッグプリントをしこたま仕掛けて調べてみると、200の時は$c->finalize_headersの前までは200,その後は0になっています。ステータスコードの入れ替えはCatalyst/Engine/Apache.pmのfinalize_headersの中だったのでこれは正しいです。

次に、$c->res->status(304)にしてから動きを見ると、なんとfinalizeが動いた様子がありません。呼び出されているのは間違いないので、どこかでオーバーライドされているはず、と調べてみると、Catalyst/Plugin/Static/Simple.pmに同名のメソッドがあって、その75行目あたりがこう。

if ( $c->res->status =~ /^(1\d\d|[23]04)$/xms ) {
    $c->res->headers->remove_content_headers;
    return $c->finalize_headers;
}

return $c->NEXT::ACTUAL::finalize(@_);

それぞれのreturnで返る値を調べるとhandle_requestに返ってきた値と同じ。この1がどこから来た物か調べると、Catalyst.pmにあるfinalize_headersの最後$c->response->{_finalized_headers} = 1;なのでこれでしょう。要は、handle_requestはfinalizeの戻り値として$c->res->statusの値を期待しているのに、Catalyst::Plugin::Static::Simpleのfinalizeが変な物を返してしまっているのが原因のようです。

ここまで分かれば後は簡単なので、とりあえずCatalyst::Plugin::Static::Simpleを外してみると、見事に問題なくなりました。ただ、これは開発時には無いと困るので、Catalyst/Plugin/Static/Simple.pmを書き換えて、$c->res->statusの値を返すように変更

--- Catalyst/Plugin/Static/Simple.pm       Wed Aug  9 00:53:09 2006
+++ Catalyst/Plugin/Static/Simple.pm      Tue Oct  3 22:18:17 2006
@@ -74,7 +74,8 @@

     if ( $c->res->status =~ /^(1\d\d|[23]04)$/xms ) {
         $c->res->headers->remove_content_headers;
-        return $c->finalize_headers;
+        $c->finalize_headers;
+        return $c->response->status;
     }

     return $c->NEXT::ACTUAL::finalize(@_);

これで、server.pl利用時にも問題ないし、mod_perl環境でも304を返せるようになりました。