"BOKU"のITな日常

BOKUが勉強したり、考えたことを頭の整理を兼ねてまとめてます。

調査で業務システムのログを久しぶりに追いかけて思ったこと

f:id:arakan_no_boku:20211114153352p:plain

目次

トラブル調査のほとんどは簡単に終わるんだけど

たまに業務システムの裏方をやってます。

繁忙月になると、ユーザからの問い合わせも増えて、それに比例する形で、運用部隊からの調査依頼の件数も増えますから、結構、忙しかったりします。

内容的には、ちょっとした問い合わせから、トラブル対応までレベルはいろいろ。

とはいえ、たいてい即答もしくは2・3時間以内・・長くても1日あれば片付きます。

調査って「だいたいこの辺りが怪しい」という「あたり」がつけられるかどうかで、かかる時間が左右されがちなのですが、今の環境は幸いにして。

  • エラーログのメッセージやスタックトレースの情報とか。
  • ソースコードを読んでロジックを追いかけるとか。
  • テスト環境で現象を再現させてデバッガで追いかけるとか。

などなど、あたりをつける方法がいろいろあるので助かってます。

とはいえ。

さっぱり「あたり」がつけられなくて調査に時間がかかってしまうような事態に絶対にならない・・わけではなく、たまーーにはあります。

 

たまに厄介な調査にぶちあたる

最近、それに久々にぶちあたりました。

正しく登録したはずのデータが消えたり・値が変わっているものがあるというクレームを受けての調査で、

  • エラーログに情報はなく。
  • ソースコードを追いかけても、おかしな点はなく。
  • 実際、何度実行しても正しく動いてしまい現象が再現せず。

という状況のため、さっぱり「あたり」がつけれれないという、厄介なパターンです。

こういう再現しないけど、ひとりの、かつ一部だけデータがおかしくなっているケースの場合、まず考えられるのは。

  • スレッドセーフでない関数か変数がどこかにあって、それが問題なのではないか
  • 正しく更新されていたデータをだれかが作業ミスとかで潰したんじゃない

みたいなことなので、とりあえず、問題が発生したと思われる日付・時刻あたりを絞って、ログを時系列においかけてみようということになりました。

 

ログで追いかけようとしたけどダメだった

ありがたいことに、昔と違い、今はログはきちんと取られていることが多いです。

今、かかわっているのも同じで、業務アプリケーションのログとして、だいたい、以下のようなものがありました。

  • アクセスログ(ログイン・ログオフ・機能の起動・終了など)
  • アプリケーションログ(正常系)
  • アプロケーションエラーログ(異常系)
  • DBアクセス・SQLログ(正常系)
  • DBアクセス・SQLエラーログ(異常系)

単体のログはしょっちゅう参照してますが、項目が不足していることはありません。

なので、なんとかなると思い始めたのですが、予定通りにはいかず頓挫しました。

どうしてかというと。

今回の調査の都合上、「問題発生しているユーザが、問題発生している機能を使って、問題の項目を更新しているときのSQL文を時系列においかける必要」があるため、複数ログを関連づけて使う必要があったのですが、ログとログを関連づけるキーが不足していて、うまく追いきれなかったのです。

詳しくいうと。

問題の発生したユーザとどの機能かはわかっていたので、アクセスログから、ユーザXXXXがその機能を使っていた日付と時間帯(タイムスタンプ)をまず探しました。

でも、それだけでは情報不足なので、アプリケーションログやSQLログ・エラーログなどを、その機能とタイムスタンプで関連づけてまとめるつもりでした。

ところが。

同じ機能が、同一時間帯にたくさん動いていて、どれが問題のあったユーザの操作によるものかわかりません。

しかも、ストアドプロシージャとかストアドファンクションとかも使っていて、その中で発行しているSQL文はログに書かれてなかったというおまけ付きで、この方法であたりをつけるのは、あきらめざるをえませんでした。

 

ログがどうなってたら良かったのか改善案を考えてみた

結局、この調査依頼は、その後取り下げられました。

詳しいことは聞いてませんが、保守担当者のミスかなんかだったらしく、えらい謝られました(笑)

なので、結果オーライではあるのですが、自分はログで追いかけられなかったのが気になってます。

何が問題だったかというと、アクセスログ以外のログの項目に、「ログインユーザID」の情報がなかったということです。

なので、特定のユーザが使っている機能(ソース名)、タイムスタンプに絞り込めませんでした。

業務システムなので、基本ログインしないで機能を使うことはありえません。

なので、仕組み上は、アクセスログ以外にも「ログインユーザID」を付与することは可能ですけど、個別のログを設計するとき、そこまで考えなかったのですね。

これは、まあ、仕方ないです。

ほかに、いっぱいやらないといけないことがある初期開発フェーズの時、ログの設計にそこまで時間をかけてもいられませんから。

 

経験値がひとつ増えたということで良しにすればいいか

改善案を考えても、また、しかり。

すぐに、改善しようなんて話にはなりません。

なぜかというと、こういう話は、しょせんは「内部の人間が年に数回あるかないかの頻度の調査のため」でしかないので、対応優先度は非常に低くなるからです。

ログはほぼ全ソースに埋め込まれているので、そのわりに、修正範囲は大きいですし。

じゃあ、せっかく気づきがあったのに無駄じゃないか・・なんて、若い時は思ったかもしれないですが・・・実はそんなことなくて。

自分の経験値のひとつとしては、しっかり残ります。。

この経験値というのは重要です。

本で読んだ知識だけでは、現場でそのまま役にたたないのは、ふつうに考えてもわかりますが、じゃあ、それが役に立つ「スキル」にどうやってなるのかというと、知識にプラス「実務で積み上げた経験値」が加わったときだと、自分は信じてるからです。

当たり前ですけど、この経験値は、自分でやらないと身につきません。

だから、「自分でやれる機会」をいただけることは、とても貴重です。

そう考えると、こんな風にブログのネタにもできたことだし(笑)、また、よい機会をもらえたということだな・・と思ったりして、また1日が終わってくわけです。

ではでは。