イノベーション エンジニアブログ


株式会社イノベーションのエンジニアたちの技術系ブログです。ITトレンド・List Finderの開発をベースに、業務外での技術研究などもブログとして発信していってます!


このエントリーをはてなブックマークに追加

ログのお話

はじめまして、ショガと申します。

晴れて9月から株式会社イノベーションで正社員として働かさせていただく事になりました。

現在イノベーションでは運用業務等を担当しています、運用業務自体は前職からのお付き合いとなり6年弱運用に関わっています、という訳で運用目線での記事をアップしていければと考えています。


私とログ

運用を担当する前は色々と開発をしていましたがログについては業種・プロジェクトによって厳格に「ログ出力規約」で出力箇所を定められている場合もあれば、フワっと「処理の開始と終了はINFOで」と口頭で伝えらる場合や、古のソースに従い出力する場合等多種多様ありました。

ログと言えば?

ログを何に利用するかと言えば、大抵は以下の用途になっているかと思います。

・処理の経過を確認する
・アプリケーションの異常を感知する

運用担当者として障害調査においてログの確認は非常に大切なプロセスなため、後者を大事にしていただきたいのですが、非機能要件という事もあり実際に稼働してみるまでは、ログ出力が引起す問題に気づけない場合が多いかと思います。

個人的なボヤキですが十分な引継ぎがなく運用フェーズに体制移行という事が多々あり(注:昔の話です)、初めて確認する設計書、ソースとにらめっこしている間に障害報告が来た場合は、まずログを確認するので、そこでつまづくと障害調査の初動が遅れがちです。


こんなログはイヤだ

では、実際に遭遇し頭を悩ました困ったログをランキング形式で発表したいと思います!!(個人的には331位までありますが、大人の事情で5位からとなります。)

5位:ログレベルがおかしい

(お困り度:★★★☆☆)

体験談

本番稼動当日は問題がなかったので帰宅したのですが、深夜に着信音で起こされました。

電話に出るとログ監視をしている方から「大量のERRORログが出ていますよ!!」と伝えられましたが、ちょっと温度差がありすぎて「はぁ…」みたいな対応をしてしまい申し訳なく思っています。

原因

ご存じとは思いますが通常ログ出力をする場合ログレベルを定め、出力レベルから緊急度・用途を切分けます、ロギングツール等の差があるかと思いますが、おおまかには下記のようなレベル感かと思います。

1.TRACE(トレース)
2.DEBUG(デバッグ)
3.INFO(情報)
4.WARN(警告)
5.ERROR(エラー)
6.FATAL(致命的)
※(CRITICALやALERTもあり)

特に規約がない場合、開発者の個人的な判断でログレベルを決めがちですが、本当に妥当なレベルか確認する場がないと、WARN レベルのログが存在しなかったり、INFO レベルのログがやたら存在したりという事が見受けられます。

今回の原因は移行対象外のテーブルをパージする処理がありましたが、過去のデータが存在しないため削除結果が0件となっており、何故か「削除対象0件」のログが ERROR レベルで定義されていた事が原因でした。

本番稼動の深夜からログ監視が開始された事で、ERROR レベルのログが検知され電話連絡で夜中に叩き起こされた次第です。

後日談

開発チームにヒアリングしたところソースレビュー時にログレベルは確認していなかったとの事なので、全体的にログレベルを見直し対応しました、その後は枕を高くして寝れたり、寝れなかったり。

4位:ログローテートしていない

(お困り度:★★★☆☆)

体験談

運用に体制移行し数週間過ぎたころにお客様のインフラチームから「ディスク容量が90%を超えました!!」と連絡があり、どこに問題があるか確認しているとログ出力ディレクトリを含むディレクトリ配下が確かに90%を超えている…

原因

そんな馬鹿なと思う方もいるかと思いますが、それなりに多いのがログのローテートがされていないという問題です、例えば TOMCAT の catalina.out 、常駐バッチの一部ログだけローテートされていないという事がありました。

ローテートする必要がないのであれば良いのですが、世代管理が適当で何故かバックアップだけが異様に溜まっていく等、規模が大きいプロジェクトではそれだけログ出力設計がずさんになるのかなという印象がありました。

何も問題がなければログを確認する事もないため、ファイルサイズが膨大になり容量を圧迫してきたところで、初めて気付くという事象です。

後日談

ログローテートの設計を見直し、適切な世代管理を実施するように対応しました、もう急なエラーに怯えずに済む(事はありませんでした)!!

3位:ログが役に立たない

(お困り度:★★★☆☆)

体験談

とある機器とのIF処理にて問題発生したようで、お客様もキレ気味に連絡してきたので「これはまずい!」と対象のログを確認すると、「システムエラーが発生しました。」の一文のみ。

原因

漢らしいログですが「いや、知ってるし!」とツッコミたくなるログ内容です、これは極端な例ですが実際遭遇しました、これ以外にも偽情報を出力していたり、ログ出力場所がおかしかったり、ログファイル名が分かりにくかったりと運用泣かせのログが色々ありました。

引継ぎ担当者もあまりログまでは詳しくないのか(そもそも時間が取れないという問題も)引継ぎ時に確認しても、「後で確認します」というセリフを残し失踪してしまう事も少なくありませんでした。

ビックリしたのは「○○処理を開始します」というログだけが延々と出力されているというのもありました、終了はないのか。

後日談

原因は例外をキャッチしどこにも投げずに握り潰すという謎仕様となっており、ソースを確認したらご丁寧にコメントで「//ここでは何もしない」という煽り文が書いてありました。

//ここでは何もしない」を「//ここで例外処理」に変更し例外のハンドリング処理を追加するように対応しました、これによりスタックトレースも出力され無事に調査ができるようになりました、やったね!

2位:ログレベルを変更できない

(お困り度:★★★★☆)

体験談

IFデータの不整合が発生しお客様の業務に支障が出たため、DB、ソースを確認したが原因がわからず ERROR レベルのログ内容ではこれ以上調査ができないため、お客様の許可を得てログレベルを DEBUG に変更したところ20分も立たずディスクを圧迫し100%に!

原因

ログ出しすぎ問題です、え!そんなところまで!?という内容の INFO の嵐に、絶対に消し忘れていたと思われる DEBUG ログ等多種多様なログが出力され、あっというまにログ出力用ディスクスペースがフルになり、各種処理が落ちるという現象が発生しました。

後日談

5位の「ログレベルがおかしい」に関連する内容ですが、一部不要なログを精査し削除する事で対応しました、何故一部かというと潔く諦めたからです!通常の運用はERRORレベルだし…

また、逆のパターンで DEBUG レベルで運用していたがログレベルを ERROR に変更したら処理が早くなるというパターンもありました。

1位:ログが出力されない

(お困り度:★★★★★)

体験談

こちらもログレベル系なのですがお客様のご要望で、ログ出力レベルを FATAL に設定し本番稼動を始めたところ、スタックトレースは出力されますがその他のエラーは何も出力されない状態になりました。

原因

スタックトレースが出力されるならいいじゃないかと思うかもしれませんが、DB操作中のエラーの場合にどのレコードを処理してエラーになったか分からない等の弊害があり、大量データを処理している場合は調査に非常に時間がかかります。

後日談

ERROR レベルにログ出力レベルを設定し運用を続けましたが、そもそもの出力情報が微妙だったため少し良くなったかなというレベルでした、これにはお手上げです \(^0^)/


番外編

なごみ系ログ

緊急事態で焦っている時にふと出会う、ホッコリするログを紹介します。

「○○処理でエラーが発生しまた。」

ホッコリ。


以上となります、見直したらほぼグチでした。

異論もあるかと思いますが個人的には3位がショッキングでした、このようにログの出力内容によって運用担当者は一喜一憂していますので、頭の片隅に入れていただければ幸いです。