結構ハマりました。。。

せっかくなので、切り分けの流れを追って解説しまぷ。
Apache2.2.10とTomcat6.10.16、RedHatでのお話
mod_proxy_ajpモジュールは、コンパイル時に組み込んでいる。



まず、こんな感じのエラーがでた。

[日付] [error] (70007)The timeout specified has
expired: ajp_ilink_receive() can't receive header
[日付] [error] ajp_read_header: ajp_ilink_receive failed
[日付] [error] (120006)APR does not understand
this error code: proxy: read response failed from (localhost

とりあえず、ApacheTomcat間の連携に使用している。
mod_proxy_ajpが悪いんじゃなかろうかというところから
情報収集を始めてみる。

 1.webで同様の事象を捜索。
 2.色々ログを見てみる。
 3.事象を再現してみる。+その時のログを見る。

というあたりから平行してアプローチ。


とりあえず1から。

ふむふむ。
どうやらmod_proxy_ajpはtooBuggyらしい。
原因はともかく、根本対応の方法としては2つだ。
1つ目は、調査日の数日前にリリースされたApache2.2.11を導入する方法。
2つ目は、昔から使われていて安定しているが、
mod_proxyの登場により非推奨となった、mod_jkに乗り換える方法

があるっぽいことが分かった。

なるほどね。最悪それにしよう。
その場合は、バグであることを証明する必要があるなぁ・・・
ということは頭においておく。

その他、実績のあるらしい「パラメータをいじる」方法がいくつかあったので
それも試してみることにしよう。


次に2をば。

開始時点で情報源となるログは以下。

 Apache
  ・error.log
  ・access.log
 Tomcat
  ・アプリのログ
  ・catalina.out

 ・error.log
  冒頭に記載したajpに関するエラーが出力されている。
  
 ・access.log
  503 Service Unableエラーがクライアントに返された出力がある。
  error.logと同時刻の出力だ。

 ・アプリのログ
  error.log、access.logと同時刻に、
  アプリの処理が行われていることが分かる。

  Apacheへのアクセスは、Tomcatまでmod_proxy_ajpを通して
  伝達しており、Tomcatはそれを正常に処理しているように見える。

  そしてもう一つ・・・
  通常処理のちょうど15分後に、SQL_Exceptionが大量の出力されている。
  スタックトレースを見るに、アプリの処理がトリガーというより、
  フレームワーク側での処理によるものに見えるが・・・
  なんだろう??

 ・catalina.out
  アプリのログ同様、Tomcatは正常に処理しているように見える。
  こちらにももう一つ・・・
  通常処理の15分後に、以下のエラーが発生していた。
  業務上全部は見せれないけど、こんな感じ。

 日付 [TP-Processor??] WARN
 org.apache.jk.core.MsgContext - Error sending end packet
 java.net.SocketException: Broken pipe

  もうちょっと調査してみると、これは通信経路(pipe)が切断された(Broken)
  ということらしい。
  
  経路?どこの? ApacheTomcat
  でもそこは、アプリログやcatalina.outから見るに、どうも通信できているらしい・・・
  とすると、TomcatApacheの戻り側が切断してるのかなぁ・・・


そして3を平行して行う。
というより、3を行う準備をしながら合間で1,2を処理。
という状態が正確なところ。

再現のために、まず状況の整理を行う。

 3-1.負荷によらず発生する。
 3-2.再起動時の初アクセスでは発生しない(したのを見たことはない)。
 3-3.30分くらい放置すると発生する。
 3-4.定期的にアクセスすると、発生しない。
 3-5.エラーは503、error.logの内容も固定。

ぱっと見、3-3と3-4がクサイξ。。。
ここら辺が肝になりそうだ。

直感的には、
 mod_proxy_ajpに関連する設定の中に、デフォルトで
 1800秒でタイムアウトする何かがあるのではないか?

という感じですよ。

ではでは、環境を整えて再現してみます。
・・・
簡単に再現しました。。。
何かと何かのタイミングが合うと、という可能性も薄いなこれは。

2の検証結果をうけての推測から、
Tomcatからの戻りの通信を確認する。(通信を確認するわけではないけど。。。
そのために、Tomcatでのアクセスログ出力を設定する。
 ☆設定は割愛

Tomcatのacccess.logを確認してみる。
・・・
何も出力されてない!

ということは、どうやら処理された内容は
TomcatからApacheへ返されていないようだ。

じゃあ、
Tomcatが結果を戻していないか、
戻せない理由があるってことかなぁ。という考えに。

netstatでポートを確認する。
AP側、DB側ともに、「ESTABLISHED」として確立されているようだ。



他に思い当たらないので、
とりあえず実績のあった設定値変更を行ってみる。


Apacheの「MaxClients」とTomcat側の「MaxThreads」をとても大きな値に変えてみた。
両方とも、とりあえず足りないことは無いだろう、
8192とかにしてみました。
結果、意味ない。
というのもまぁ、
 3-1.負荷によらず発生する。
という時点で意味ないのはわかる。でもやるの。一応。



あー。とりあえず休憩 λ...



ここで、あることに気づいた。
色々設定やなにやら変更して、ApacheTomcatに再起動をかけている。
この再起動までの操作が15分を超えないとき、pipeBrokenのエラーは発生しない。
再起動かけてるんだからそりゃそうだろうって思うかもしれない。
じゃあ、再起動後、現在調査中のエラー操作を行わない場合、
放置してればpipeBrokenが発生するのか?というと、
しない。


ということは、
エラーの起こる操作が、
pipeBroken発生の原因になっていることは間違いない。


もう一度見直してみよう。

 エラー操作から15分後に以下が発生。
 ・大量のSQLException
 ・pipeBroken(通信経路の切断)

想像するに、
Tomcatのcatalina.outに出力されている正常処理だったというログは
あくまでアプリが実行したときに書かれたもので、
「正常な戻り値だったこと」を保証するものではない。

ということであったら・・・


Tomcataccess.logに何も出力されていないのは、
アプリがSQLを投げた時点でレスポンスが返ってこなくなったから。
ApacheはTimeoutし、503でエラーを返す。
15分後、DBにアクセスできなかったことを、大量のSQL Exceptionと
pipeBrokenで通知。。。



これじゃね?



じゃあ、APとDBの間にあるものがAPとDBの通信を遮断している?


いやでもね、
netstatでみたとき、エラー後のAPとDBの接続は「ESTABLISHED」なんだよね。
とは言え、この仮説には可能性があると思ったので、
ちょっと考えてみた。

APとDBのあるもの、それは、ロードバランサ(LB)とファイアウォール(FW)。
どちらもウチで設定したものではないので、
SQLのポートと、1800秒というキーワードで心当たりは無いか聞いてみる。


・・・



ビンゴきました。。。


アクセスが無い場合、1800秒でコネクションを切断する設定が
FWにしてありました。
しかも仕様で、コネクションを切断したことは
利用側(この場合AP、DB)には切断したことを通知しないらしい。
てことで、「ESTABLISHED」だと思っているAP側は、
ふつーにアクセスして帰らぬ人となる、と・・・。


これをとりあえず無制限にしてもらって試すと、
もうエラーは起こりませんでした。


ということで、
私の環境で起こった下記エラー

[日付] [error] (70007)The timeout specified has
expired: ajp_ilink_receive() can't receive header
[日付] [error] ajp_read_header: ajp_ilink_receive failed
[日付] [error] (120006)APR does not understand
this error code: proxy: read response failed from (localhost

の原因は、
FWのコネクション切断設定が原因であった
ということで。。。


エラーからじゃわかんないよね・・・´ω`