岡崎図書館HP大量アクセス事件で思い出した「低負荷で落ちるシステム」

岡崎図書館HP大量アクセス事件の真犯人はどうやら「コネクションプーリング」らしいことが

2010/8/31 ここから追記

当初、『見えてきています。』という内容で投稿しましたがコネクションプーリングは関係ないそうです。間違った事実を広めてしまいましてすみませんでした。DBとの接続ができなくなる何らかの不具合という事象の原因としてtwitter等でコネクションプーリングを原因とみる人を見かけたので自分もそう思い込んでいました。プール可能な接続数を使い切るのではなく、コネクションプーリングを使わないでDBと接続する際のDB側のコネクション数の上限に達してしまう事象だったようです。

コネクションプーリングによる接続数の上限は通常Webサーバ側での制限事項になりますので似ているようで大きく違いますね。DBが異なるAPを積んだ２台以上のWebサーバから接続を受けているケースを考えますと片方のWebサーバでコネクションプーリングの上限に達したとしても他方のWebサーバは元気に動きます。ところがDB側のコネクション数の上限にまで達してしまうとWebサーバ2台とも接続不能になってしまいます。以上、追記でした。

そのバグを作りこんだのは誰か？というのはプログラマ一人の責任から発注者、受注者の両者を踏まえた責任分界から、利用者の利用形態まで様々な要素が入り交じった問題となりますので今後の解明を待ちたいところです。

さてこの件ではコネクションプーリングをONにしたのに破棄についてよく考えていなかったというお行儀の悪さが報道されました。私個人の経験から言いますと、世の中にはこのような製品・サービスもありますのでこういった観点からテストを行なっていれば発見し得るバグだったのではないかな、というように考えております。ネットや新聞で知った内容から考えるに、正常時の負荷しか検証していなかったのではないかという疑念を感じます。

日本シー・エー・ディー小俣さん＋豆蔵さんと「ゼロから見直すWebシステムの負荷テスト・性能テスト」セミナーを開催します

しかしそのような推論をしてもあまり建設的ではないですし、この件だって犯人探しをするよりも日本のシステム業界を全身させるために必要な神様のいたずらだったと考えたほうが得策です。私個人も何か貢献できればと思い、負荷テストで発見できなかった「低負荷で落ちる」システムについて述べたいと思います。ただし、私自身がその継続的な開発・運用のメンバーから外れておる関係で細部の記録にアクセスできません。記憶を中心に書きますのでおかしな部分があったらコメント欄等にて補足をいただけますと幸いです。

私が担当したシステムではごく一般的なDBサーバにごく一般的なWebサーバを組み合わせて使用。デフォルト値のコネクション数を使って動いていました。DBサーバとWebサーバのセグメントの違いから、間にNW機器が置いてありました。

負荷テストも行い、ほぼMAXで使用した場合のスループットを測定しました。DB単体でのスループットからオーバーヘッドを割り引いて見積もったスループットは、負荷テスト結果とほぼ同じような値が出ました。

しかし残念ながら本番で謎の障害が発生します。ログから発見されていたエラーがあったのですが、ユーザ側からの問い合わせがなかったために情報共有をして事態を見守ることに。後日、何件目かでユーザ側ヘルプデスクに問い合わせが発生、ログ上のエラーはユーザ側に影響のある「障害」に格上げされました。

そこで調べに入ったのですが、パフォーマンス情報等によると「使われていない」時間帯です。コネクションプーリングということで接続数が上限に達したような障害ケースが強く疑われたわけですが、どうもそういうわけではなさそうです。よくある、ユーザ側は画面を閉じていてもセッション上に接続情報が維持され……というケースでもないようで、障害発生時点のコネクション数は1本とか2本という数字でした。

結局は「人間」の部分がすべてを解明してくれました。「どうも昼休み明けに発生することが多い気がする」という証言を手がかりに、そうだとしたら負荷ではないところが怪しいのでは？という疑いの方向転換が行われます。ならばということで同じ環境を作って「昼休み」を再現することになりました。しかし「昼休み障害」は発生しません。障害調査用の環境と本番環境の違いを検証すると、NW機器が置いてあるか否かの1点しか違いがありません。

ではNWレベルの障害では、ということで本番環境上でNWの監視を行ってみることになりました。IPアドレスが重複する何か、とか、NW機器が再起動する何か、とかが見つかるかもしれません。すると、謎のですが、DBサーバめがけてRESTパケットが飛んできて、Web側もDB側もコネクションを維持しているつもり十分なところでDB側がコネクションを切ってしまうという事象が発見されました。原因はNW装置が15分以上使用されていないコネクションを切る設定になっていたので。そんなもんあるのか？と思ったのですが装置によってはそういう設定もあるようです。

これはDB側に「予期せぬ原因でコネクションが切れました」というエラーログが記録された事実と一致します。障害調査環境でRESTパケットを投げてみたところ（私は投げ方がわからなかったので分かる人にやってもらったのですが）同じエラーログが記録されました。

そしてその状態でWeb側というと、自分はコネクションが切れたことを知りません。そのため「あるもの」と思って切れたコネクションを使ってしまってその一連の問い合わせが終了してしまうということになりました。

もっとも、障害の一番初めに対症療法的かつ当てずっぽう半分で、Webサーバ側の「コネクションの有効性を確認してから接続する（Validate Connection）」オプションを有効にしましたが、これが機能して障害は一時的に完全に止まっていました。全体的な構成を見て、コネクションの有効性を確認するオプションをOFFにし、NW装置が勝手にコネクションを切断するまでの時間をコネクションプーリングが維持される上限の時間（Connection Lifetime）よりも長く取って完全に対処完了となりました。

この件はもうずいぶん前の話なのですが、気を遣った部分だったせいか資料もない割に今でもよく覚えています。

感想を一言で述べるならば、数十人の人間の想像力が数千人の人の行動に及ぶわけがない、ということでした。私は1年以上開発の現場から遠ざかっておりますが、他の人の話など聞くと、障害の発生を防ぐための努力の一部は発生後の影響を最小限に抑えるための努力に振り返られても良いのでは？と思うことがあります。