【Spring Boot】例外を握りつぶしたエラーの追い方|原因がログに出ないときの調査メモ

Spring Bootを触り始めたころ、私はエラーを見るのがかなり苦手でした。

赤い文字がたくさん出ると、それだけで「壊したかも」「どこから読めばいいのかわからない」と焦ってしまいます。特にJavaやSpring Bootは、スタックトレースが長くなりやすく、初学者のころは画面いっぱいのログに圧倒されていました。

ただ、実務に近いコードを見ていると、本当に怖いのは「エラーが出ること」ではなく、「本当の原因がログに出ないこと」だと感じるようになりました。

その典型が、例外を握りつぶしてしまうケースです。

この記事では、Spring Bootで例外をcatchしたあとに何もログを出さず、処理を続けてしまった場合を例に、エラーの追い方を整理します。
あわせて、自分で調べてもどうしても原因がわからないときに、業務では有識者に助けを求めることも大事だと感じたので、その観点も残しておきます。

例外を握りつぶすとは何か

Javaでは、例外が起きそうな処理を try-catch で囲むことがあります。

外部API、DBアクセス、ファイル読み込み、JSON変換などは、失敗する可能性があります。そのため、例外をcatchして処理すること自体は悪いことではありません。

問題は、catchしたあとに何もせず、失敗した事実を見えなくしてしまうことです。

try {
    // 失敗するかもしれない処理
} catch (Exception e) {
    // 何もしない
}

このようなコードは、一見するとアプリケーションが落ちないので安全そうに見えるかもしれません。

でも、実際にはかなり危険だと感じます。

例外が起きたのにログが残らないため、あとから調査するときに「本当はどこで失敗したのか」がわからなくなるからです。

しかも、例外を握りつぶした直後には問題が表面化せず、少し離れた場所で別のエラーとして出ることがあります。この場合、ログに出ているエラーだけを見ると、原因を間違えやすくなります。

実例:Serviceで例外を握りつぶしてnullを返してしまう

ここでは、ユーザー名を取得するAPIを例にします。

Spring initializrでプロジェクトを作成します。

以下のような設定です。

本来は、Serviceでユーザーを探して、見つかったら名前を返すだけの処理です。
ただし、Repositoryで例外が起きたときに、Service側で例外を握りつぶして null を返してしまうコードにします。

まず、Controllerです。

package com.example.demo.user;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class UserController {

private final UserService userService;

public UserController(UserService userService) {
this.userService = userService;
}

@GetMapping("/users/{id}/name")
public String getUserName(@PathVariable Long id) {
User user = userService.findUser(id);

// userがnullだと、ここでNullPointerExceptionになる
return user.getName();
}
}

次に、Serviceです。

package com.example.demo.user;

import org.springframework.stereotype.Service;

@Service
public class UserService {

private final UserRepository userRepository;

public UserService(UserRepository userRepository) {
this.userRepository = userRepository;
}

public User findUser(Long id) {
try {
return userRepository.findById(id);
} catch (Exception e) {
// 悪い例:例外を握りつぶしている
return null;
}
}
}

最後に、Repositoryです。ここでは説明用に、わざと例外を発生させています。

package com.example.demo.user;

import org.springframework.stereotype.Repository;

@Repository
public class UserRepository {

public User findById(Long id) {
throw new IllegalStateException("DB接続に失敗しました");
}
}

Userクラスはシンプルにしておきます。

package com.example.demo.user;

public class User {

private final Long id;
private final String name;

public User(Long id, String name) {
this.id = id;
this.name = name;
}

public Long getId() {
return id;
}

public String getName() {
return name;
}
}

プロジェクトはこんな感じです。

この状態で、次のURLにアクセスします。

GET /users/1/name

ブラウザには、Spring BootのWhitelabel Error Pageが表示されました。

Whitelabel Error Page 

There was an unexpected error (type=Internal Server Error, status=500).

この時点では、画面だけを見ても何が起きたのかはほとんどわかりません。
そのため、Spring Bootを起動しているターミナル側のログを確認します。

実際に出たログのうち、記事に必要な部分だけを抜粋すると次のようになります。
実行時刻、PID、ローカルパスなどは伏せています。

[日時] ERROR [PID] --- [demo] [nio-8080-exec-1]
o.a.c.c.C.[.[.[/].[dispatcherServlet] :
Servlet.service() for servlet [dispatcherServlet] in context with path []
threw exception [Request processing failed:
java.lang.NullPointerException:
Cannot invoke "com.example.demo.user.User.getName()" because "user" is null]
with root cause

java.lang.NullPointerException:
Cannot invoke "com.example.demo.user.User.getName()" because "user" is null
at com.example.demo.user.UserController.getUserName(UserController.java:21)

このログからわかるのは、Controllerの getUserName メソッドで user.getName() を呼んだとき、usernull だったということです。

一見すると、Controllerのnullチェック漏れだけが原因に見えます。

もちろん、nullの可能性がある値をそのまま使っていることも問題です。
ただし、本当の原因はそこだけではありません。

今回、Repositoryでは次の例外を投げています。

throw new IllegalStateException("DB接続に失敗しました");

本来であれば、「DB接続に失敗しました」というメッセージが見えてほしいところです。
ところが、実際のログにはこのメッセージが出ていません。

なぜかというと、Serviceで例外をcatchしたあと、何もログに出さずに null を返しているからです。

catch (Exception e) {
    return null;
}

つまり、Repositoryで起きた本当の例外はServiceで消えてしまい、Controllerでは「userがnullだった」という結果だけが表に出ています。

これが、例外を握りつぶしたときの怖さだと思います。

このエラーをどう追うか

このケースでは、ログに出ているのは NullPointerException です。

まず見るべきなのは、ログに出ている行です。

UserController.getUserName(UserController.java:21)

ここから、Controllerのこの行で user がnullだったことがわかります。

return user.getName();

ここで終わらせずに、次に確認するのは「userはどこから来たか」です。

User user = userService.findUser(id);

つまり、次に見るべき場所は userService.findUser(id) です。

Serviceを見ると、次のコードがあります。

public User findUser(Long id) {
    try {
        return userRepository.findById(id);
    } catch (Exception e) {
        return null;
    }
}

ここでようやく、かなり怪しいコードが見えてきます。

例外が起きた場合に null を返しているため、Controller側では「ユーザーが見つからなかった」のか、「DB接続に失敗した」のか、「想定外のバグが起きた」のか区別できません。

私は以前、ログに出ている最後のエラーだけを見てしまいがちでした。
でも、このようなケースでは「最後に出たエラー」は結果であって、原因ではないことがあります。

そのため、エラー調査では、値がどこで変わったかを一段ずつ戻って見るのが大事だと感じました。

Controllerでnullになっているなら、Serviceが何を返したかを見る。Serviceがnullを返しているなら、その条件を見る。catch句があるなら、そこで失敗が隠れていないかを見る。
このように少しずつ戻っていくと、いきなり全部を理解しようとするより落ち着いて追える気がします。

ログを出すだけで調査しやすくなる

まず最低限の改善として、catchした例外をログに出します。

package com.example.demo.user;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Service;

@Service
public class UserService {

private static final Logger log = LoggerFactory.getLogger(UserService.class);

private final UserRepository userRepository;

public UserService(UserRepository userRepository) {
this.userRepository = userRepository;
}

public User findUser(Long id) {
try {
return userRepository.findById(id);
} catch (Exception e) {
log.error("ユーザー取得に失敗しました。id={}", id, e);
return null;
}
}
}

ポイントは、例外オブジェクト e もログに渡すことです。

log.error("ユーザー取得に失敗しました。id={}", id, e);

これで、ログにはServiceで失敗した事実と、元の例外のスタックトレースが出るようになります。

[日時] ERROR [PID] --- [demo] [nio-8080-exec-1]
com.example.demo.user.UserService :
ユーザー取得に失敗しました。id=1

java.lang.IllegalStateException: DB接続に失敗しました
at com.example.demo.user.UserRepository.findById(UserRepository.java:9)
at com.example.demo.user.UserService.findUser(UserService.java:19)

このログがあるだけで、調査のしやすさがかなり変わります。

Controllerで NullPointerException が出ていても、その前にServiceでDB接続失敗が起きていたとわかるからです。

ただし、ログを出して null を返すだけでは、まだ問題が残ります。Controller側では結局 user がnullになり、別のエラーにつながる可能性があります。
そのため、ログを出すことは第一歩ですが、設計としては「失敗をどう呼び出し元に伝えるか」も考える必要があります。

nullで返すより、意味のある例外にする

今回の例では、Repositoryで失敗した場合に null を返すより、例外として呼び出し元に伝えたほうが原因を追いやすくなります。

たとえば、独自例外を作ります。

package com.example.demo.user;

public class UserSearchException extends RuntimeException {

public UserSearchException(String message, Throwable cause) {
super(message, cause);
}
}

Serviceでは、元の例外を握りつぶさず、原因として保持したまま投げ直します。

package com.example.demo.user;

import org.springframework.stereotype.Service;

@Service
public class UserService {

private final UserRepository userRepository;

public UserService(UserRepository userRepository) {
this.userRepository = userRepository;
}

public User findUser(Long id) {
try {
return userRepository.findById(id);
} catch (Exception e) {
throw new UserSearchException("ユーザー取得に失敗しました。id=" + id, e);
}
}
}

ここで大事なのは、元の例外 e を捨てないことです。

throw new UserSearchException("ユーザー取得に失敗しました。id=" + id, e);

cause として元の例外を渡しておけば、スタックトレースから「Serviceでユーザー取得に失敗した」だけでなく、「RepositoryでDB接続に失敗した」というところまで追えます。

ログのイメージは次のようになります。

com.example.demo.user.UserSearchException: ユーザー取得に失敗しました。id=1
    at com.example.demo.user.UserService.findUser(UserService.java:18)
Caused by: java.lang.IllegalStateException: DB接続に失敗しました
    at com.example.demo.user.UserRepository.findById(UserRepository.java:9)

Caused by が残っていると、かなり調査しやすいです。

私はエラーを見るとき、まず最後の行や自分のクラス名を探していました。
でも、例外を投げ直している場合は、Caused by を追うことで本当の原因に近づけることがあります。

ControllerAdviceでエラー応答を整える

例外を投げ直すようにすると、今度は利用者に返すレスポンスをどうするかが気になります。

Spring MVCでは、@ControllerAdvice@ExceptionHandler を使って、Controllerで発生した例外をまとめて扱えます。公式ドキュメントでも、@Controller@ControllerAdvice@ExceptionHandler メソッドを定義して例外を処理できることが説明されています。

たとえば、今回の UserSearchException を500エラーとして返す場合は、次のように書けます。

package com.example.demo.common;

import com.example.demo.user.UserSearchException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.RestControllerAdvice;

@RestControllerAdvice
public class ApiExceptionHandler {

private static final Logger log = LoggerFactory.getLogger(ApiExceptionHandler.class);

@ExceptionHandler(UserSearchException.class)
public ResponseEntity<ErrorResponse> handleUserSearchException(UserSearchException e) {
log.error("ユーザー検索処理でエラーが発生しました", e);

ErrorResponse response = new ErrorResponse(
"USER_SEARCH_ERROR",
"ユーザー情報の取得に失敗しました"
);

return ResponseEntity.internalServerError().body(response);
}
}

レスポンス用のクラスも用意します。

package com.example.demo.common;

public class ErrorResponse {

private final String code;
private final String message;

public ErrorResponse(String code, String message) {
this.code = code;
this.message = message;
}

public String getCode() {
return code;
}

public String getMessage() {
return message;
}
}

このようにすると、利用者には内部のスタックトレースを見せず、必要なエラーメッセージだけを返せます。

{
  "code": "USER_SEARCH_ERROR",
  "message": "ユーザー情報の取得に失敗しました"
}

一方で、サーバー側のログには原因を残せます。

ERROR ... ApiExceptionHandler : ユーザー検索処理でエラーが発生しました
com.example.demo.user.UserSearchException: ユーザー取得に失敗しました。id=1
Caused by: java.lang.IllegalStateException: DB接続に失敗しました

この形なら、利用者向けの表示と、開発者・運用者向けの調査情報を分けられます。

以前の私は、エラーを見せないためにcatchする、という感覚がありました。
でも今は、エラーを隠すのではなく、見せる相手に応じて情報を整理するほうが大事なのだと思うようになりました。

それでも原因がわからないときは、抱え込まない

ここまで、例外を握りつぶした場合の追い方を書いてきました。

ただ、実務ではコードだけを見ても原因がわからないことがあります。
自分の調査不足ではなく、そもそもアプリケーションの外側に原因があることもあるからです。

たとえば、インフラ側の一時的な問題でDB接続が不安定になっていたり、同じ検証環境を使っている別の人の操作と競合して、登録結果が想定と変わっていたりすることがあります。
テストで期待値と実際の値が一致しないときも、自分のコードだけが原因とは限りません。データの初期状態が違っていた、他の人が同じデータを更新していた、参照しているログの時間帯を見間違えていた、というようなこともあります。

こういう原因は、ひとりで画面を見続けていてもなかなか気づけません。

特に初学者のうちは、「自分がわかっていないだけかも」と思って、必要以上に抱え込みがちです。
でも、業務では有識者に助けを求めることも大事だと思います。

もちろん、何も調べずに丸投げするのはよくありません。
ただ、ある程度ログを見て、再現手順を確認して、どこまで追ったかを整理したうえで相談するなら、それは立派な調査の一部だと思います。

相談するときは、「エラーが出ました」だけだと相手も困ってしまいます。
私は、最低限次のような情報をまとめてから聞けるようになりたいです。

発生した操作、期待した結果、実際の結果、確認したログ、怪しいと思っている箇所、すでに試したこと。
このあたりを短くまとめるだけでも、相手が状況を追いやすくなると思います。

例外を握りつぶしていないか確認する観点

エラー原因が追えないときは、まず catch の中身を見ます。

catch (Exception e) {
    return null;
}
catch (Exception e) {
    // TODO
}
catch (Exception e) {
    return false;
}

このようなコードがある場合、例外が発生しても呼び出し元には別の値として伝わります。
その結果、後続処理で NullPointerException になったり、「なぜfalseなのか」がわからなくなったりします。

また、広すぎる Exception をcatchしていないかも気にしたいです。

catch (Exception e)

すべての例外をまとめてcatchすると、想定していた失敗と、想定外のバグが同じ扱いになりやすいです。
たとえば「ユーザーが存在しない」と「DBが落ちている」は、同じ失敗ではありません。

ログに残す情報も大事です。

どの処理で、どのIDや条件で失敗したのか。元の例外が Caused by として残っているのか。スタックトレースが出ているのか。
このあたりが残っていると、あとから原因を追いやすくなります。

ただし、何でもログに出せばよいわけではありません。パスワード、トークン、個人情報などをそのままログに出すのは避ける必要があります。
調査に必要な情報を残しつつ、出してはいけない情報は出さない。このバランスも実務では大事だと感じます。

エラー調査の流れをメモしておく

今回のようなケースでは、私は次の流れで追うと整理しやすいと感じました。

まず、ログに出ている例外名を見ます。次に、自分のクラス名が出ている行を見ます。そこで使われている変数がどこから来たのかを戻り、ServiceやRepositoryのcatch句を確認します。
途中で return nullreturn false があれば、失敗が別の値に変換されていないか考えます。

そして、元の例外がログや Caused by に残っているかを確認します。

特に大事なのは、最後に出たエラーだけで判断しないことです。

NullPointerException が出ていても、原因は「nullチェック漏れ」だけとは限りません。
その前の処理で、例外を握りつぶしてnullを返していた可能性があります。

一方で、どれだけ見てもコード上の原因が見つからないこともあります。
そのときは、検証環境、DBの状態、他の人の操作、インフラの状態、ログの見方など、自分の担当コード以外にも視野を広げる必要があります。

この切り分けは、経験がないと難しいです。
だからこそ、調査した内容を整理したうえで、有識者に相談することも大事なのだと思います。

エラーは出したほうが助かることもある

エラーが出ると、やはり少し焦ります。

でも、例外を握りつぶしたコードを見てみると、エラーが出ないことのほうが怖い場面もあるとわかりました。

きちんと例外が出ていれば、失敗した場所がわかります。
Caused by が残っていれば、元の原因まで追えます。
ログにIDや処理名が残っていれば、再現や調査もしやすくなります。

逆に、例外を隠してしまうと、アプリケーションはその場では動き続けるかもしれません。
でも、後から別の場所で壊れたり、間違ったデータが登録されたりする可能性があります。

Spring Bootのエラーを見て「怖い」と感じていたころの私は、エラーを出さないことが良いことだと思っていました。

今は少し違います。

必要なエラーは、ちゃんと出たほうがいい。
ただし、利用者に見せる情報と、ログに残す情報は分ける。
そして、元の例外はできるだけ捨てない。

さらに、自分だけで抱え込まず、必要なときは人に見てもらう。
エラー調査は、コードを読む力だけでなく、状況を整理して相談する力も含まれるのだと感じました。

まとめ

Spring Bootでエラーを調査するとき、本当に怖いのは赤いログそのものではなく、原因が見えない状態だと感じました。

特に、例外をcatchしたあとに何もログを出さず、nullfalse を返してしまうと、本当の原因が消えてしまいます。

ただ、実際に動いているコードでこのような状態になっているものは見たことがあります。。限られた時間で調査するのは視野も狭くなるし焦ります。だからこそ設計段階で気を付けるべきですが。。実際には様々な事情でできないこともあります。

Spring Bootを学習している間は、エラーを消すことだけを目指すのではなく、あとから追える形で残すこと。
そして、自分で追った内容を整理して、必要なときに相談できること。

この2つを意識していきたいです。