とあるアクセス解析のような Web アプリ。Web をブラウジングしているオーディエンスにユニークな ID を割り振って、アクセス状況に応じてタグをつける。アクセスされる URL ごとに「このタグをつける」という設定を事前にしておいて、実際にアクセスがあったオーディエンスにタグをつける。技術的にはデータベースにタグの設定情報、ユーザーエージェントのクッキーに ID を持たせ、KVS にある ID のユーザーエージェントが持っているタグ情報を入れるというアプリケーションだ。

タグを付与した時点でタグの ID をログに落としている。ログをバッチで集計してデータベースに保存している。この Web アプリのユーザーにはこのデータを使って、あるタグをもつユーザーエージェントがどのくらい居るのか、オーディエンスのボリュームをレポートしている。

このレポートの数値がどうもおかしい。2 つのタグ設定 A と B がある。A は単にとある URL にアクセスした際に付与される設定。B は A と 同じ URL へのアクセスが必要で、かつ別のタグを持っていないと付与されない。B のほうがより絞った設定をしているのに、レポートをみると A よりも B のほうがボリュームがあると出ていた。これはなぜかをしらべてほしいという報告だった。

まず調べるのはタグ付けの設定。ここになんらかの不備がないか。報告された挙動でしかるべきな設定がされていたのかもしれない。その場合は単にユーザーに設定方法をレクチャーするのか、あるいは UI が直感的でないので修正が必要になるかもしれない。

今回のケースでは設定に不備はなかった。ただしそこにたどり着くまでがやっかいで、ユーザーは当時とは設定値を変えてしまっていて、問題発生当時の状況を再現するのが大変だった。ユーザーへのヒアリングと、UI の操作ログをたよりに状況を再現する。設定には問題がなく、アプリケーション側、ロジックかデータか、に問題があることになる。

次に見るのはアプリケーションのログと Web サーバのアクセスログだ。当該のタグ ID でログを絞込んで眺めてみると、ある不可解なうごきがみえてきた。問題となっている URL にアクセスするごとに A、B つのタグが付き、もう一度アクセスすると B が消えているように見えるのだ。

ちなみにアプリケーションのログデータは fluend で hive に投入してもらっている。クエリをなげてログを抽出できるので、こうした調査のときにも便利だ。

いちどついたタグが外れるのにはいくつかの条件がある。たとえばデータサイズを抑えるために、ひとつの ID がもてるタグの数を制限し、個数いっぱいの場合には優先度の低いものを捨てるという処理がある。アプリケーションログにはアクセス時に付与したタグとすでに持っているタグを出力しているため、この仮説が原因かどうかをすぐに調べることができる。このようにいくつかの仮設をしらべてみたが、あてはまるものは見つからなかった。

さて、いよいよロジックが怪しくなってきた。ロジックを読む前にもう少し範囲を絞り込んでおきたい。

タグ情報を保存する KVS にはいくつかのアプリケーションがアクセスしている。どのアプリケーションのアクセスでデータが意図しない変化をしているのか、ログデータからもう少し絞り込みたい。KVS のデータの変遷も fluend で hive に入れてもらっている。hive をひいて、どういう操作の時にデータが意図しない変化をしたのか調べてみると、やはり今回疑っているアプリケーションの時のみだった。

ロジックを追う前に、最小のテストケースをつくろう。今回の場合は当該 URL に 2 度アクセスするというのが再現手順だ。一度目に 2 つのタグが付き、リロードするとひとつ減る。

次に手元でアプリケーションを動かす。リポジトリを pull し、本番と同じデータを手元に持ってくる。ローカルの RDBMS と KVS をスタート。RDBMS には本番と同じデータを投入する。hosts でアクセスがローカルに飛ぶように変更。plackup でアプリを立ち上げ、ローカルの Web サーバで plackup したプロセスが listen しているポートにリクエストをプロキシする。

この状態で再現手順を実施してみる。予想通り再現できた。

今回の場合はロジックのどこがあやしげか、まだ検討がついていない。こんなときはデバッガで絞り込んでいくことにする。perl のデバッガ経由で plackup しよう。怪しげな部分にブレークポイントを埋めておいて、perl -dS plackup foo.psgi として起動する。ステップ実行しながらおかしな場所を絞りこんでいって、やっと問題の場所を特定できた。ふつうにロジックに問題が合った。今回のようなケースの考慮が漏れていたようだ。

修正方針をたてる。ロジックを変えることで別のケースをカバーできなくなることはないか。そもそももともとのこういうコードになっていることに明確な意図はあるのか。もともとこのコードを書いた人と相談しながら考えて方向性を決めた。

今回の問い合わせでないケースで影響がでているかどうか。同じような設定をしているユーザーがいないかどうかはデータベースを引けばわかる。本来の挙動とどのように異なってしまっていたのか。今回の場合はユーザーから見るとレポートの数値が実際と異なっていた。状況をビジネスサイドに共有。ユーザーへの案内は彼らの判断だ。

今回のケースは隣の同僚とふたりで取り組んだ。前半のログ調査は同僚の功績だ。また hive や fluend などログ環境を整備してくれている同僚にも頭があがらない。

手元での状況の再現、とくに本番と同じデータの再現はとても面倒だ。でもゴールが見えている作業ではあるので、そのぶん気楽さがある。最初の原因をしぼりこむ作業が、ゴールが見えず大変な部分だろう。