久しぶりに仕事で perl を使った。
現在仕事を受けている会社で、サーバートラブルがあった。
そこで、トラブルに遭遇したユーザーを特定したいという。
ここでのサーバートラブルは、「サーバーに接続できなかった」というトラブルだ。
そのため、サーバーには接続できなかった人を特定するログは残っていない。
しかし、リバースプロクシを入れてあったため、プロクシにはログが残っている。
ただ、このログは通常の WEB アクセスのログであり、ユーザーを特定できる情報が残っていない。
実は、問題のあったアクセスは POST アクセスなのだ。
そして、POST の body データとしてユーザーを特定できる情報が入っている。
body として送られるデータは一般的に大きいため、普通はログに残すような設定にしない。
つまりは、問題のある URL にアクセスした個人を特定したいのだが、その個人を特定する情報は記録されていない。
いや、まだ手はある。
知りたい URL アクセスには個人特定情報は入っていないが、その前に必ずアクセスする URL は GET アクセスで、この時は URL パラメータとして個人を特定できる情報があるのだ。
そして、これは「直前の URL」なので、おそらくは問題となる URL のアクセスの際にも、IPアドレスは変わっていないだろう。
ただ、IP アドレスは使いまわされる可能性がある。
IPアドレスだけで「同じユーザーのアクセス」と認定するのは危険で、user agent 情報も一緒に使うのが良いだろう。
まとめると、つまりこういうことだ。
・特定 URL にアクセスして、接続できなかった (status が 302だった）個人を特定したい。
・特定 URL アクセスには個人特定の情報はないので、直前の別 URL アクセスの際の情報を使用したい。
・２つの URL の間が「同じユーザー」であることは、IP アドレスと user agent の一致で確認。
さて、これを２万行ほどあるログに対して、処理したい。
トラブルの事後処理なので、できるだけ早急に。
あぁ、これは perl の出番だな、と瞬時に判断したが、perl 使うの久しぶり。
大丈夫だろうか、と思いながらスクリプトを書き始める。
結論から言えば、うっかりミスはあったが過去のノウハウは活きた。
WEB サーバーのログは、基本的にスペース区切りなので、情報を得たいときはスペースで分割する。
…という風に、処理慣れしていないプログラマなら思うだろう。
perl では、１行にスペース区切りで複数のデータが入っているときは、
split;
というたった一命令で分割処理が終了する。
以前、perl の命令は暗黙のデフォルトが多いという話を書いた。
本当は、split 命令は、「分割したいデータ」と「分割する文字」を与え、「分割した内容を受け取る変数」に代入を行う必要がある。
しかし、全部省略すると、$_ （通常は、現在注目している行）を連続したホワイトスペースで分割して、@_ （一時的な配列）に入れてくれる。とても便利。
なので、WEB サーバのログでも、split で分割したくなってしまうのだ。
でも、WEB サーバーのログの中には、「スペースが許容されている情報」が収められている。
サーバーにどのようなアクセスがあったか、という情報と、user agent は、内部にスペースが入るのだ。
そのため、スペースで区切ると、情報の途中で区切られてしまうし、分割後の「情報」の位置が安定しないしで、処理しづらいことこの上ない。
もちろん、ログ内で混乱が起きない工夫はあって、スペースを含む情報は " （ダブルクオート）で括られることになっている。
だから、ダブルクオートを見つけたらその内部をひと固まりとして処理するようなプログラムを書けば…
というのは、正攻法だけどひたすら面倒くさくて時間のかかる道。
発想を変えよう。最初に、" で区切ってしまえばいい。
アクセス情報と、user agent は " で括られているのだから、この段階で適切な位置にある情報が取得できる。
IP アドレスやアクセス時刻は、" で括られない情報なので、上記処理で手に入った断片を、さらにスペースで区切る。
これで、各種情報が手に入る。
過去に何度も WEB サーバーのログを処理していたので、こういう処理ノウハウはすぐに思い出した。
さて、まずは、「直前の GET アクセス」から個人を特定できる情報を拾い出そう。
これは、特定の URL を条件として、正規表現で拾い出してやれば終わりだ。
IP アドレス、user agent もすでに取得してあるので、この２つの組をキーとした連想配列に、個人特定情報を保存しておく。
つづいて、情報が欲しい「特定 URL にアクセスしたとき」の処理も作る。
この URL も、正規表現で拾い出せばよい。
ただ、この「特定 URL」は、一つではない。
末尾部分がサービスの違いを示す数値になっていて、一人のユーザーが複数の「数値の違う」URL にアクセスしている可能性もある。
そのため、URL の末尾に入る数値も一緒に記録してほしい、とのリクエストだった。
これは、正規表現の ( ) （グルーピング演算子）で取り出す。
ここでの正規表現は「データを得るためのもの」ではなく、if 文の実行条件を示す「比較」にすぎない。
しかし、「比較」でデータを取り出せてしまう、というのも perl の便利な部分だ。
条件はもう一つあった。この、特定 URL のアクセスが「302 エラーになった時」だ。
これも、ログにはステータスが入っているので、302 の時を条件に入れればよいだけ。
さて、無事条件に合うアクセスがあったら、時刻と URL 内部の数値と、個人特定できる情報を１行にまとめて出力してほしい、というリクエストだった。
個人特定情報は、先に書いたように、IP アドレスと user agent に紐づいた形で保存してある。
これを使えばいい。
時刻は、サーバーログに入っている形式と、求められている形式が少し違ったので、変換する。
ログに入っているのは [20/Nov/2019:15:30:28 +0900] という形式。
必要なのは、2019-11-20 15:30:28 という形式。
これも、正規表現でグルーピングを使えば必要な情報が得られるので、整形して出力するだけ。
出力は、２通り用意してほしいと頼まれていた。
まずは、エラーが出たすべてのアクセス。
もう一つは、エラーが出たことで繰り返しアクセスする人も多かったので、「同じ URL への同じ人のアクセスは、初回のみを記録して後は省略」したもの。
まずは、エラーが出たすべてのアクセスを出力し、ファイルに残す。
続いて、プログラムに少し追加。
URL と個人特定情報を組として、一度出力したら「1」を記録するようにした。
この記録があったら出力済み。事前に確認し、出力処理を飛ばすようにした。
これで出力した情報もファイル化する。
さて、ここまで整形した情報を得るまで、１時間程度。
久しぶりの perl としては、まずまずだろう。
しかし、データを送信してしばらくたって、先方から「おかしい可能性」を指摘される。
どうも、「同じ URL への同じ人のアクセス」を省略したほうのデータが、少なすぎるように思うというのだ。
しばらくプログラムを見てみるが、すぐに原因が特定できない。
「すべて」を出力したファイルに対し、unix コマンドの sort と uniq を駆使して「同じ URL への同じ人のアクセス」を省略したファイルを作ってみる。
明らかに数が違う。データ件数で、15 倍くらいの情報があった。
これ、連想配列のアクセス方法を間違えているためだった。
最近使っている、Javascript でも PHP でも、連想配列アクセスには [ ] を使う。
でも、perl は連想配列は { } だった。
完全に自分の頭から抜け落ちていた「常識」に気づくまで、１時間くらい。
これに気づいて修正したら、出力データ件数が増えた。
出力データを wc してみる。行数や語数を数える unix コマンドだ。
「すべてのデータ」出力は、改良前と後で同じ件数だが、出力データサイズが微妙に違う。
改良前と後のファイルを diff して違いを探す。
どうやら、件数は同じでも、個人特定情報の部分が違う。
改めてプログラムを見て、連想配列アクセスを間違えていたため、個人情報の紐づけが正しくなかった、と判明。
なので、先に作った全件データは誤り。新しい方が正しい。
この正しいデータをもとに、sort | uniq したデータと、プログラムで「同じ URL への同じ人のアクセス」を省略したファイルは、同じ件数・同じ出力サイズだった。
sort した関係で順番などが異なっているのだけど、別の方法で集計しても、プログラムの集計と同様になったことが確認されたので、このデータは正しいと判断。
ここまで、最初の依頼から２時間半ほど。
データを送って確認してもらい、おそらく正しいだろうという判断になった。
＃そもそも、確実に正しいか確かめる方法はない。
正しいデータがないから、こんなプログラムをしているのだもの。
…と、今日記を書いていて、ここで終わろうと思ったところ、ちょうどバグ報告が来た。
出力の中に、「個人特定情報」が入っていない行がある、とのことだった。
元になるアクセスログを開き、「報告すべきエラー行」を特定する。
それから、そのエラー報告に含めるための、「個人特定情報」を拾い出せる、事前の行を探し出す。
…ここで、ミスをした。
というのも、「個人情報」は当然ないので、バグ出力に含まれる情報で行を探したが、実は該当行が２行あったのだ。
しかし、僕は「時系列で上にあった行」だけを見つけて、その行を元に周囲を調べ始めてしまった。
どう考えてもデータはおかしくないので、自分のプログラムのミスだろうと探すこと３０分以上。
いろいろ確認してもおかしくないので、データに戻り、再度おかしいところを探す。
この作業中、やっと自分の過ちに気づく。
そして、２行目の該当行を元に、同じ IP アドレスでアクセスしている「事前の」行を調べると、存在しなかった。
事前アクセスがないので、「事前のアクセスから」情報を引っ張ってくることはできない。
プログラムには問題はなく、データの問題だった。
ここまで確認して、報告。
ついでに、事前データはないものの、「事後の」アクセスから個人を特定できたので、その情報も報告。
ひとまず作業終了となった。
昨日日記に書いた「遊びの」プログラムもそうなのだけど、こうしたパズル的なプログラム作業は、やっていて楽しい。
保守性とか読みやすさとか考えないで、ただ動くプログラムを書けばいいからね。
仕事なので時間制限もあったりするのだけど、それも踏まえて「最短時間で解決するにはどうすればいいか」というような段取りから考えるのが楽しいのだ。
同じテーマの日記(最近の一覧)
別年同日の日記
申し訳ありませんが、現在意見投稿をできない状態にしています。 |