Java鉄板ログ調査

調査の鉄則

Java + Angular のシステムについて、今までたくさんの調査をしてきた。

中には難易度が高く、有識者に助けを求めたものや、長時間、上司とレビューしたものもあった。そして、どの人からも教えられる解決策は同じだった。それは…

とにかく成功断面と徹底比較すべし！

とにかく成功している環境またはバージョンをまず再現する。

そして、ヘッダーもパラメータも、成功断面との差分を徹底的に0にする。

そこから1つ1つ間違い探しをする。メソッド単位＞行単位＞条件単位…

エラーが想像できない場合は、誰に聞いてもこの方法が鉄則だった。

Javaのログ調査基礎

Javaのエラーログは非常に親切丁寧であるが、その分出力される量も多い。以下はサンプル。

[INFO] Starting the application...[http-nio-8080-exec-1]
[INFO] Request received: GET /secure[http-nio-8080-exec-1]
[ERROR] A security exception occurred.[http-nio-8080-exec-1]
j.p.s.s.o.exception.CustomSecurityException: Security violation detected
    at j.p.s.s.o.controller.SecureController.secureEndpoint(SecureController.java:15)
    at j.p.s.s.o.App.main(App.java:10)
Caused by: org.springframework.security.access.AccessDeniedException: Access denied due to missing credentials.
    at o.s.s.a.i.AffirmativeBased.decide(AffirmativeBased.java:70)
    at o.s.s.a.i.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:220)
    at o.s.s.w.a.i.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:130)
    at o.s.s.w.a.i.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
    at o.s.s.w.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
Caused by: org.springframework.security.authentication.AuthenticationCredentialsNotFoundException: No authentication credentials found.
    at o.s.s.a.p.ProviderManager.authenticate(ProviderManager.java:123)
    at o.s.s.w.a.UsernamePasswordAuthenticationFilter.attemptAuthentication(UsernamePasswordAuthenticationFilter.java:110)
    at o.s.s.w.a.UsernamePasswordAuthenticationFilter.doFilter(UsernamePasswordAuthenticationFilter.java:120)
    at o.s.s.w.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)    ... 5 more

[ERROR] A security exception occurred. より下の部分は、エラーの詳細を出力した、スタックトレースと言われる箇所で、これをもとにエラーの原因を調査する。

ログの読み方

根本原因を知りたい場合は下から読む

ログのエラーの原因となった主要な行を抽出すると、以下の4行。

[ERROR] A security exception occurred.[http-nio-8080-exec-1]
j.p.s.s.o.exception.CustomSecurityException: Security violation detected
…
Caused by: org.springframework.security.access.AccessDeniedException: Access denied due to missing credentials.
…
Caused by: org.springframework.security.authentication.AuthenticationCredentialsNotFoundException: No authentication credentials found.
…

これは下から、

    1. AuthenticationCredentialsNotFoundException が発生したため、AccessDeniedExceptionが発生
    2. AccessDeniedException が発生したため、CustomSecurityException が発生
    3. CustomSecurityException によって、[ERROR]行のログが出力された

と読むことができる。

根本原因は一番最後に出力されている、AuthenticationCredentialsNotFoundExceptionとなる。

アーキ部品や、サーバーエラーなど、アプリ表層より、もっと深い部分のエラーである可能性が高い場合は、ここから確認する。

ソースコード調査の場合は上から読む

シンプルにアプリロジックでエラーが起きている可能性が高い場合は上から読む。

例えば、以下のようなエラーを考える。

  1. アプリロジックで必須項目であるプロパティがnullになった
  2. java.lang.NullPointerExceptionが発生した

エラーの根本は最後に出力されるNullPointerExceptionとなるが、大切なのは①の、なぜアプリロジックで必須項目がnullになったのか、の方。

これがソースコード上のどのロジックで発生したかを確認したいので、先ほどのソースコードで言えば、一番上のj.p.s.s.o.exception.CustomSecurityException クラスを確認する。

o.s.s.a.p.とか、j.p.s.s.o.とかって何？

これはパッケージの階層を表している。知ってないとわからないよね…

Caused by: org.springframework.security.authentication.AuthenticationCredentialsNotFoundException: No authentication credentials found.
    at o.s.s.a.p.ProviderManager.authenticate(ProviderManager.java:123)

例えば、上記のログで、o.s.s.a.p.は、以下の階層を表す。（各フォルダの頭文字を取っている）

org.springframework.security.authentication.ProviderManager

固定文言が出力されたらGrep

以下のログを見てほしい。

[ERROR] A security exception occurred.[http-nio-8080-exec-1]

フレームワークが出力するログは、日時やリクエスト内容など、調査に必要な有益な情報を出力するものがほとんどで、『A security exception occurred.』のように、汎用性の低そうな固定文言を出力するのは珍しい。

こういった独自性の高い固定文言が見つかった場合は、フレームワークではなくアプリの固有実装、つまり、自分たちで実装している可能性が高い。

そのため、この固定文言を検索ワードとしてソースコードをGrepすれば、すぐに実装箇所が見つかることがある。

http-nio-8080-exec-1 はスレッド番号

nioはNew I/Oの略称らしく、execの後の番号は、スレッド番号を指す。

基本的に１つのリクエストは同じスレッド内で処理されているため、複数の行でも、execの後の番号が同じであれば、同じリクエスト内での処理であると判別できる。

Apacheのログ調査

ここまで見てきたログは、APサーバーであるTomcatから出力されている。

Tomcatのログは、アプリケーション側からカスタマイズできるため、時に不正確な場合がある。（アーキのロジックレベルでバグがある場合なので、ケースとしてはレア）

WebサーバーであるApacheログは、サーバーレベルでカスタマイズしていないとバグは起きない。かつ、Apacheは歴史も長く、純粋なログとして信頼性が高い。

これらのことから、情報自体は非常に少ないのだが、リクエストの前後関係を見るうえで、Apahceログを参照したい場合がある。（上記の通りアーキレベルのバグを疑う際など）

また、APサーバーを経由せずに、Webサーバー（ブラウザ）から直接外部にリクエストを送信する場合にもApacheのログを参照する。

Apacheのログは以下のような形式となっている。

"DELETE /app-name/api/methodName HTTP/1.1" 500 9555
  • HTTP/1.1：プロトコル
  • 500：ステータスコード
  • 9555：送信バイト数

クライアントへの回答のしかた

クライアントに調査結果を回答するには、以下を説明する。

  • 事象：何が起きたか。どこで発覚したか（ユーザーレベルか、ITかなど）。
  • 背景：前提で話しておくべき内容があれば記述。
  • 影響範囲：データの影響範囲だけでなく、ステークホルダーレベル（ユーザーはもちろん、別の開発部署等）の話も含める。
  • 対応：どのような初動対応を実施したか。
  • 原因：原因
  • 対策：今後の対応

根拠資料

  • スタックトレース：実際のエラーログ
  • 実装コード
  • 公式サイトの情報：フレームワークなどの挙動について言及する場合は、フレームワーク提供元の公式サイト情報であれば使用可能

ブログの記事などは根拠にならないのでクライアントには絶対に提出しないこと。

公式ドキュメントからの根拠の探し方

  1. 公式ドキュメントのサイトを特定する
  2. siteコマンドでページを特定する

例えば、SpringSecurityに起因する調査の場合は、公式サイトである、https://spring.pleiades.io/spring-security/reference/ が根拠資料となる。

ここから例えばJwtについての記事を探したい場合は、ブラウザの検索窓に以下を入力する。

site:https://spring.pleiades.io/spring-security/reference/ jwt

site:[URL] [keyword]とすることで、ブラウザはURLの中からキーワードを使用している記事を取得してくれる。

site-command

siteコマンドは検索オプションが色々あるので適宜調べる。

site:[URL] [keyword] OR [keyword2] ※OR検索
site:[URL] -[keyword] ※keywordは除く
site:[URL] "[keyword]" ※keyword完全マッチ
site:[URL] "[keyword1*keyword2]" ※ワイルドカードも使用可能
site:[URL] intitle: "[keyword]" ※ページタイトル検索

調査テクニック

調査では膨大なログの中から特定の情報をキーに原因となるログを抽出する作業が必要になる。

サクラエディタのGrep機能が優秀なので、これを使うと良い。（持っていない人はインストール簡単なので入れておくこと推奨）

サクラエディタでの調査

ファイルを開く際に、文字コードをUTF-8に指定して開かないと、日本語が文字化けする。

サクラエディタを新規で開き、ファイル＞開く 、ここで文字コードセットをUTF-8に指定してファイルを開く。

基本的なファイル検索

特定のキーワードを含むファイルを探したい場合。

検索＞Grep

  • 条件：検索対象文字列
  • ファイル：*.java #test  ※半角スペースで区切って複数条件指定。#は除外フォルダ。

■よく使用するオプション

  • サブフォルダからも検索する：指定しないと下位のフォルダが検索されない
  • 正規表現
  • ファイル毎最初のみ検索：指定しないと同じファイルでいくつもHitする

■Excelで整理したい場合

サクラエディタの正規表現で、スペースやコロンをタブに書き換えるなどして、Excelに貼り付けた時にうまくセル分割されるように整形する。

参考：サクラエディタのGrep結果をエクセル用に整形する

検索＞置換

  • 置換前：(^.*?)\((.*),(.*)\)\s+\[(.*)\]:(\s+)
  • 置換後：$1\t$2\t$3\t\4\t

ログファイルの整形

すでにエラーログが特定できている場合に、正規表現を使用してログファイルの中から必要な情報だけを抽出する。

検索＞置換

以下の正規表現で、キーワードを含む行以外を削除できる。キーワードにユーザーIDなどを指定して、ログを絞っていく。

^(?!.*キーワード).+\n

あとは用途に応じて正規表現を勉強しましょう。

ファイルサイズの大きいログを分割する

テキストもExcelもそうですが、各アプリケーションには開くことのできるファイルサイズの最大値が決まっている。

ログファイルはものによっては膨大な量になるため、しばしばこの最大値を超えて開けなくなる、なんてことが起こる。

パワーシェルを使用して、以下のコマンドで分割できる。

$i=1;
$filePath="./sample.log";
$separateCount=5000;
$outFileName="output";
cat $filePath -ReadCount $separateCount | % { $_ > $outFileName"_"$i.log; $i++ }

パワーシェルは主題ではないので詳しい説明は割愛するが、前半は変数定義、最後のcatの行ではざっくり以下の処理を行っている。

  • catでファイル読み込み
  • -ReadCountで読み込む行数を指定
  • 『|』はパイプ構文。左辺の戻り値に対して続けて右辺の処理を実行する
  • 『%』ForEach-Objectと同義
  • 『$_』に左辺の戻り値が代入される
  • 『>』はOut-Fileと同義。ファイルをアウトプットする
  • $outFileName以降で、ファイル名を指定

コメント

タイトルとURLをコピーしました