PHP エラー発生時の IIS アクセスログ

エラー発生時に 500 が記録されるとは限らない！

IIS アクセスログを解析するにあたり、普段からどのようなエラーが記録されているかあらかじめ知っておくことは大変重要です。

例えば、実際にはあまり良いことではありませんが普段から、あるエラーが発生しているまま運用していたとします。

ある日、サーバーで何か大きな問題が発生してアクセスログを確認したとします。そしてそこで始めて、もともと発生していたエラーに気付きます。

すると、普段から発生しているエラーを見て「なんだ！このエラーは！原因はこれだ！」と考えてしまうことになります。

しかし、普段からそのエラーを発生させたまま運用できていたわけですから、それが少々記録されていたとしてもそれが直ちにその「大きな問題」の原因とはできないはずです。

もちろん、何か問題が積もり積もって問題が顕在化してくる可能性もあるので、それが原因である可能性もあるでしょう。

しかし、普段から発生しているものなのだからあまり気にしなくても良いかもしれないし...

いずれにしても、ログをみてある程度「あ、普段と違うぞ」ということがピンとこないといけないのです。

500 サーバー内部エラー

HTTP のサーバーレスポンスステータスとして、500 は "サーバー内部エラー" を表します。

従ってサーバー側、例えば ASP や ASP.NET などでコード上のエラーなどが発生した場合には、 IIS のアクセスログにはサーバーのステータスとして 500 が記録されます。

例えば、次のようになります。

#Software: Microsoft Internet Information Services 7.0
#Version: 1.0
#Date: 2009-04-11 06:46:44
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username 
c-ip cs(User-Agent) sc-status sc-substatus sc-win32-status time-taken
2009-04-11 06:46:44 ::1 GET /test.asp |5|ASP_0177_:_800401f3|Server.CreateObject_Failed 80 - 
::1 Mozilla/4.0+(co...CLR+3.5.30729;+.NET+CLR+3.0.30618;+MS-RTC+LM+8) 500 0 0 3754
2009-04-11 06:49:00 ::1 GET /test.aspx - 80 - 
::1 Mozilla/4.0+(co...CLR+3.5.30729;+.NET+CLR+3.0.30618;+MS-RTC+LM+8) 500 0 0 9019

上側のログが ASP のエラー、下側が ASP.NET のエラーです。

どちらも 500 が記録されています。

では、PHP で同様にスクリプトでエラーが発生した場合のエラーログを見てみましょう。

2009-04-11 06:50:45 ::1 GET /test.php - 8080 - 
::1 Mozilla/4.0+(co...CLR+3.0.30618;+MS-RTC+LM+8) 200 0 0 2033

なんと 200 が記録されています。

200 というのは HTTP ステータスコードで OK を表しており、正常終了した時のステータスです。

しかし、PHP の場合は実際の処理はエラーで終わっているにもかかわらず、200 が記録されています。

ちなみに、Wfetch でみると次のようになり、実際にクライアントに 200 OK を返していることが確認できます。

尚、これは PHP に限ったことではなく、特に IIS と独立して動作する CGI を扱う場合に見られる動作なので、 CGI を使う場合には特に、どのような場合にどのようなエラーが記録されるか（あるいはされないのか）あらかじめ確認しておくと良いでしょう。