失敗の記録は財産　～　Discard Old Pluginを使ってみました。

7月 06, 2013

失敗の記録は財産　～　Discard Old Pluginを使ってみました。

わたしは、定型ジョブを cronやWindows タスクスケジューラでうまく扱えない時や、ジョブの所要時間の検証のために、Jenkinsを使って記録を残すようにしています。

今回は、トラブルの事例をふまえて、ジョブのチェックに役立つプラグインや感じたことをご紹介します。長めのエントリなので、お急ぎの方は、文末をご覧くださいませ。

リリース前から活躍

現在お守りをしているシステムは、Webアプリケーションではありますが、バッチファイルを起動してデータ生成をしたり、定時になったらデータを関連システムに反映させる必要があります。また、そのWebアプリ自身では、タスクスケジューラーのような機能は持っていないので、当然、OS標準もしくはそれ以外のジョブコントロールの仕組みを使う必要があります。

さらに、複数バッチの実行が必要で、どうしても排他を考慮しないといけないため、特別なクライアントやDBを用意せず、自分もメンバもベンダの方もシンプルに実行結果がWebから確認できるように、Jenkinsを使うことにしました。（こちらのエントリも参考にどうぞ！）

他と比べていないので主観的になってしまうかもしれませんが、Jenkinsを使ったことは、リリース前の設定の段階で、バッチが想定どおりに動くか、実データを投入してどれぐらいバッチに時間がかかるのか、というのを見積もるのに大変有効でした。自分でファイルを世代管理しなくとも履歴を残すことができるので、ベンダの担当コンサルの方にデータを提供するのも、非常にやりやすかったのです。

実運用でのトラブル

すったもんだあったのですが、システムはカットオーバーし、実運用に入りました。進化中のWebアプリに対し、Jenkinsを使ったバッチは大変忠実にお仕事をこなしてくれました。Jenkinsを使っていてもリソースには問題ないようだったので、そのままJenkinsを使ってたくさんのバッチや、Windowsサーバで処理できないものをCentOSで実施する、といった使い方をしていました。

ところが、6月のある時点から、本来定時になったら他システムに連携するはずのデータができない状態が発生しました。
なぜだろうとJenkinsを見ると、あるジョブが２時間以上も滞留してしまい、排他が必要で、かつ毎時に実行されるべきジョブがブロックされていたのです…。

明らかにジョブが滞留するはずがないことが判っていたので、すぐにこのジョブを中断し、キューに溜まっていたジョブを流したので、いったんは解決しました。ですが、数時間して、この状態が再現してしまいました。自分だけなら良いのですが、他の方の仕事にも支障が出てしまい、ジョブが正常に回るのが前提のWebアプリだったため、いくらWebの画面から操作をしても、データが関連システムに流れていってくれないのです。

また再現する可能性があったため、中断したビルドはひとまず保存し、そのときの状況を細くするコメントを残しました。もちろん、そのときのコンソールログは、ベンダサポート側に提出し、同時刻のアプリケーションサーバ側でなにか問題が起きていないか確認をお願いしました。

でも、原因がいまひとつわからず。

問題のバッチは、アプリケーションサーバ（APサーバ）のAPIを叩いて処理を行うようになっています。ログを見るからに、APIを呼び出して、そのままずっと応答を待って滞留しているようでした。この時点ではインフラの問題なのか、APサーバに問題が起きているのかが判りませんでした。リソースモニタを見ても、負荷がかかっているような状況には見えません。

ベンダもインフラ担当の側でも、設定変更は特にしていないとのことで、なかなか問題解決にいたりません…。

問題再発

滞留を見つけたら、中断してキューにあるジョブを流す…というのを数回実施し、ごまかしながら稼動させていましたが、ついには毎時頻繁に滞留が起こるようになりました。手動でバッチを実行するとすぐに処理が終わることもあるので、APIの呼び出し時、名前解決ができていないからうまくAPIが呼べないのでは、という予想はハズレのようでした。

そうこうしているうちに、Webの画面も正常にレスポンスが返らなくなり、バッチも滞留ばかり発生。この時点で、セッションがうまく張られない／腐ってしまってるのかもしれないと考え、インフラ担当の方にもご指示をいただいて、OS再起動をしました。（OS再起動だと障害扱いです…）

その後、週末をはさんで２日くらいは問題なさそうだったのですが、週明けの夜間バッチを確認すると、滞留が…。
再び対応をしてから、出社して様子を見ていると、毎時ジョブの滞留が発生するようになりました。ですが、すべての回で失敗するわけではありません。

ベンダサポート側でも、「原因がつかめない、滞留している時にはAPサーバに対するアクセスの記録がないので、インフラの問題ではないですか」という状況でした。

ただし、失敗も成功も両方あるので、たぶんAPサーバかフロントでリクエストを一時受けするWebサーバが、リクエストをちゃんと処理できてないのではないかと考えました。（レスポンスを返せなければ、ログには出てこないですし）

ポーリングして失敗の記録をチェックする

そこで、1分毎にAPIのエンドポイントのURLをポーリングするJenkinsのジョブを作って、API呼び出しが詰まるのかどうか監視することにしました。（Zabbixなどもありますが、記録をすぐに確認したかったので、Jenkinsを使いました）

ちなみに、JenkinsにはURLをポーリングするプラグインがあります。こちらだと、StatusCodeが200以外は失敗として扱われてしまいます。わたしはWebサーバもしくはApサーバが反応を返せる状態なのかどうかを調べたかったので、このプラグインは使わず、PowerShellを使ってポーリングしました。
（パラメータなしで単純にAPIのエンドポイントにアクセスするとInternal Server　Errorなのですが、それでもレスポンスがちゃんと返るなら正常、なにもレスポンスが無いなら、Webサーバへもリクエストが届いていないので何かおかしい、という判断です）

通常、クライアントごとにデフォルトのタイムアウト値にしたがって、うまく接続ができない場合はタイムアウトで処理が終了するはずですが、バッチのプログラムはタイムアウトを長くしているようで、そのため自動では中断されずに滞留しているようです。

調査用のポーリングスクリプトでは、HttpClientのタイムアウトを長く設定し、バッチと同じように長めにレスポンスを待つようにして、Jenkins側のタイムアウトプラグインで、指定時間を越えたらエラーと判定するようにしました。（メールも飛ばすようにしました）

このプラグインのいいところは、タイムアウトして中断させた場合、ビルドのコメントに自動で「ｘｘ分でタイムアウト」という情報が付けられることです。

このポーリングの結果、以前よりも短い間隔でAPI呼び出しのリクエストが滞留する状況なのが浮き彫りになりました。同じタイミングで、問題のバッチもタイムアウトしているのも明らかになりました。

非常に良くない状態なので、ベンダサポートに急いで調査を依頼したのですが、なかなかお返事・結果をもらえません…。

その間にも毎分のポーリングのエラーが発生し、成功も失敗も記録を残すようにしたため、短時間でもそれなりの数のログが溜まってきました。
テキストベースで、さほどリソースは消費しないはずですが、システムが怪しい状況の中で、監視目的とは言えディスクを消費してしまうのもよろしくないので、できれば失敗の記録だけを残したい....。

なにか無いかと考え、幸いにも見つけたのが、Discard Old Pluginでした。

失敗の記録だけ保持したい！

「まさにこれだー！」という思いで、早速プラグインを投入。Authorは、Jenkins勉強会でお話したことのあるSHIFTの方で、日本語でのリリース情報と、MLでの案内もあったので、まずは安心です。

最新バージョンでは、UIは英語のみのようですが、こちらで、保持しなくてもいいビルドステータスをチェック。
保存後、すぐに毎分のビルドが開始となり、数百溜まっていた記録は、最新のビルド２～３件と、その他は失敗したビルドのみを残すまでになってくれました。

これで、わたしだけでなく、インフラチームの方にもベンダの方にも、滞留が発生していることがよりハッキリし、調査のためのログもきちんと残すことができるようになりました。

その後の顛末

滞留が発生したらインフラチームにもメールを飛ばすように設定し、あとはベンダの回答を待つばかりだったのですが、やきもきしている間に、OSがブルースクリーンになり、再起動という結果に…。

しかも、再起動後はポーリングのジョブに滞留／エラーが発生しなくなりました(^^;;;;

その結果、「やっぱりOSの問題だったのでは？」ということで、ベンダ側の調査もいったん打ち切りに近い形になってしまいました。わたしとしては、APIのエンドポイントが反応しなくなっていたのは明らかだし、前に再起動させた時は数日して問題が再発しているので、できるだけ協力して問題解決したかったのですが…。

後で、ポーリングの記録だけでなく、そのタイミングのnetstatのデータも保持していれば良かったと思いました…。こちらに関しては、再起動後あと数日しないとなんとも言えないので、ポーリングのジョブは有効にしておき、netstat 情報もコンソールに出力するようにして、様子を見ています。