はじめに
はじめまして。入社1年目の藤本です。 webアプリケーションを開発する際には、様々なエラーに遭遇します。 私は、研修で初めてSpring Bootをつかってwebアプリケーションを作った際に、数多のエラーと出会い、気が滅入りました。 入社するまで、Spring BootはおろかJavaにさえ触れたことのなかったので、どう解決していくのか見当もつかない状態でした。 そこで本記事では、webアプリケーション開発を行う際に遭遇するエラーとの戦い方を、Spring Boot を例に新人目線で語っていこうと思います。
ポイント1：エラーログを読む
最初のポイントは、エラーログを読むことです。 エラーログを読むことで、どのような問題が起こっているのかという現状を知ることができます。
エラーログを読むという行為は、エラーを解消するうえでは当たり前なことですが、初心者にとってはなかなか難しいです...。 以下に、エラーを起こした時のログを載せます。
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v3.2.1)
2024-01-16T14:29:26.699+09:00 INFO 21436 --- [ main] com.example.error.ErrorApplication :
Starting ErrorApplication using Java 20.0.2 with PID 21436 ()
2024-01-16T14:29:26.704+09:00 INFO 21436 --- [ main] com.example.error.ErrorApplication :
No active profile set, falling back to 1 default profile: "default"
2024-01-16T14:29:28.044+09:00 INFO 21436 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer :
Tomcat initialized with port 8080 (http)
2024-01-16T14:29:28.058+09:00 INFO 21436 --- [ main] o.apache.catalina.core.StandardService :
Starting service [Tomcat]
2024-01-16T14:29:28.059+09:00 INFO 21436 --- [ main] o.apache.catalina.core.StandardEngine :
Starting Servlet engine: [Apache Tomcat/10.1.17]
2024-01-16T14:29:28.162+09:00 INFO 21436 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] :
Initializing Spring embedded WebApplicationContext
2024-01-16T14:29:28.166+09:00 INFO 21436 --- [ main] w.s.c.ServletWebServerApplicationContext :
Root WebApplicationContext: initialization completed in 1375 ms
2024-01-16T14:29:28.632+09:00 INFO 21436 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer :
Tomcat started on port 8080 (http) with context path ''
2024-01-16T14:29:28.642+09:00 INFO 21436 --- [ main] com.example.error.ErrorApplication :
Started ErrorApplication in 2.64 seconds (process running for 3.045)
2024-01-16T14:29:32.663+09:00 INFO 21436 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] :
Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-01-16T14:29:32.665+09:00 INFO 21436 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet :
Initializing Servlet 'dispatcherServlet'
2024-01-16T14:29:32.668+09:00 INFO 21436 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet :
Completed initialization in 2 ms
2024-01-16T14:29:32.746+09:00 ERROR 21436 --- [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.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2] with root cause
java.lang.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2
at com.example.error.ErrorController.hello(ErrorController.java:14) ~[classes/:na]
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:578) ~[na:na]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:262) ~[spring-web-6.1.2.jar:6.1.2]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:190) ~[spring-web-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:917) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:829) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) ~[spring-webmvc-6.1.2.jar:6.1.2]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:903) ~[spring-webmvc-6.1.2.jar:6.1.2]
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:564) ~[tomcat-embed-core-10.1.17.jar:6.0]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) ~[spring-webmvc-6.1.2.jar:6.1.2]
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.17.jar:6.0]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-6.1.2.jar:6.1.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.2.jar:6.1.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-6.1.2.jar:6.1.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.2.jar:6.1.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-6.1.2.jar:6.1.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.2.jar:6.1.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) ~[tomcat-embed-core-10.1.17.jar:10.1.17]
私はSpring Bootのログを初めて見たとき、あまりの長さに読めるものではないなとエラーログを読むことを諦めました。が、エラーログを読まずに直感でエラーを直そうとすると、多大な時間を要するので絶対にやめた方がいいです。 エラーログ全てを読まなくてはいけないわけではなく、エラーメッセージの先頭部分を読むと、起きている例外やエラー元がわかることが多いです。しかし、Spring bootのエラーログで目当てのログの始まりを見つけるのは困難です。なぜなら、Sprinhg bootのエラーログはとても長いからです。加えて、ログの後半はエラーが発生するまでの過程を示すスタックトレースなので、読んでもよくわからない自分が作成した覚えもないファイル名ばかりが書かれています。 ログのフォーマットを知っておくと、ログがどんな始まり方をしているのかがわかるため、見つけやすくなります。 コンソールを遡ってエラーログの始まりを見つけるために、ログのフォーマットを紹介します。
デフォルトのログフォーマット
Spring Bootのデフォルトのコンソールログでは、以下の項目が順に出力されます。
| 項目 | 内容 |
|---|---|
| 日付 | 処理が実行されたタイミングの日時 |
| ログレベル | ERROR、WARN、INFO、DEBUG、TRACE からなる実行時に影響を及ぼす度合いを表すもの |
| プロセスID | 実行中のプログラムの識別子 |
| --- | 実際のログメッセージの開始を区別するセパレータ |
| アプリケーション名 | spring.application.nameが設定されているアプリケーションの名前を、角括弧に囲んで表示 |
| スレッド名 | 処理が属するスレッドの名前を、角括弧に囲んで表示 |
| ログメッセージ | ログの詳細なメッセージ文、エラーが発生するまでの過程を示すスタックトレース |
例：
2023-11-23T13:39:54.548Z INFO 35705 --- [myapp] [ main] o.s.b.d.f.logexample.MyApplication : Started MyApplication in 2.545 seconds (process running for 2.907)
Spring Bootのデフォルトのログフォーマットでは、日付が先頭に来るため、そこからがログの始まりであることがわかります。 日付が先頭に来ている行の中で、ログレベルがERRORであり、 角括弧に囲まれたスレッド名の直後のエラーメッセージを読むことで、エラー内容を知ることができます。 前述のログでは、33行目から以下のようなエラーログが始まっていることがわかります。
2024-01-16T14:29:32.746+09:00 ERROR 21436 --- [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.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2] with root cause
java.lang.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2
at com.example.error.ErrorController.hello(ErrorController.java:14) ~[classes/:na]
at
エラーメッセージに発生した例外名(ArrayIndexOutOfBoundsException)が見つかります。また、その直後に「Index 2 out of bounds for length 2」というメッセージがあり、配列のインデックスが範囲外であることが原因のエラーということが読み取れます。加えて、対象のクラスと行番号(ErrorController.java:14)もログに記載されているため、どこを直せばいいかわかります。
ロギングライブラリを使う
Javaを用いた開発では、LogbackやLog4j2などのロギングライブラリを使うことができます。 ロギングライブラリを使うことで、以下のようなことができるようになり、エラーログが読みやすくなります。
- ファイルへのログ出力
- ログ出力の色分け
- ログのフォーマット指定
- 出力するログレベルの指定
ログのフォーマットでは、各項目の前に項目名を付けることで、目的のエラーメッセージを探しやすくなるのでオススメです。
date:2024-01-09 11:02:26 thread:http-nio-8080-exec-2 X-Track: level:ERROR logger:org.thymeleaf.TemplateEngine message:[THYMELEAF][http-nio-8080-exec-2] Exception processing template "login"
level:ERRORを検索することでエラーログの始まりが見つけられます。ERRORだけだと、その下のメッセージ内にもたくさん出てきて見つけづらい...。
ポイント2：デバック機能を使う
2つ目のポイントは、デバック機能を使うことです。デバック機能を使うことで、処理の流れにそって動作を確認できるので、トラブルの直接原因を見つけやすくなります。
デバック機能では、プログラムを止める箇所(ブレークポイント)を指定し、止めた箇所から1行ずつ動作確認することができます。 Eclipse、IntelliJなどの統合開発環境(IDE)や、VS codeのような高機能なエディタに、デバック機能は用意されています。
開発しているアプリケーションの規模が大きくなってくると、多くのクラスが連携しており、具体的にどこのクラスのどの部分がエラー原因か分かりづらくなってきます。また、ログにエラーは吐かないけれども、期待した結果がでないこともしばしばあります。
そんなときにデバック機能が役立ちます！
動作確認したい箇所にブレークポイントをつけて、処理がどこまで正常に進んでいるのか、コードのその時点で変数にどんな値が代入されているかを確認できます。そうすることで、想定通りに動いていない箇所がはっきりとわかります！
ポイント3：公式ドキュメントを参照する
3つ目のポイントは、公式のドキュメントを参照することです。公式の情報を確認することで、戦う必要のないエラーとの戦闘を避けて通ることができます。
ネットには、ソースコードがそのまま書かれていたり、日本語で丁寧に解説してくれていたりするような、とても便利な情報が多く転がっています。 しかし、こうした公式以外が発信している情報は正確さが担保されているわけではなく、信憑性にかけます。 また、情報が古くバージョンの違いなどが原因で、情報の通りに実行していくだけではエラーが発生してしまうことも多々あります。
実際に、ネットの公式以外の情報を参考にしていて、以下のようなトラブルが起きました。
- Spring Securityのバージョンアップでコードの書き方が大幅に変更され、過去の記事の通りでは全く動かない。
- Mavenの依存関係のバージョン指定が古く、それだけでSpring Bootが起動しない。
こうしたトラブルを避けるためにも、最初に公式ドキュメントを確認することをおススメします。 APIのJavadocやSpring公式ドキュメントなど正確さが担保された情報源をあたる癖をつけることで、そもそもエラーに出会う回数を減らしていけるはずです。
ポイント4：エラー原因とその対処方法をまとめておく
4つ目のポイントは、エラー原因とその対処方法をまとめておくことです。そうすることで、将来出会ったエラーへの対処が楽になったり、エラーを起こさないように考える力が身についたりすると思います。
「なんかいろいろやってたら、エラーが消えた！」では学びになりません。 何が原因でそのエラーが起こっていたかあやふやなままだと、同じようなエラーでまた詰まってしまいます。 一度、原因と対策をしっかりとまとめておくと、似たようなエラーに遭遇した際に確認できます。また、よくあるエラーを覚えることができ、エラーメッセージから具体的なエラー原因を推察できるようになったり、コーディング中にエラーを起こさないように気を付けられるようになったり、いいことがたくさんです。
私はプロキシ関連のエラーに何度も苦しめられたので、プロキシとの戦いの予感を感じ取れるようになりました。プロキシ関連エラーは、社内のネットワークから外部のネットワークに通信する際に起こります。その対処方法は使用するライブラリやアプリケーションなどの通信元によって異なります。そのため、残念ながら過去にプロキシに詰まった経験とまとめた対処方法の中に、現在の問題の直接的な解決方法がないことも多いです。しかし、原因がプロキシであることまで分かれば、その通信元でのプロキシの通し方を調べればよいことがわかります。このように、過去のエラーと全く同じエラーでなくても、原因が推察できるところまで行けば、対処方法も探しやすくなります。
おわりに
Spring Bootでwebアプリケーション開発を行う際に遭遇するエラーとの戦い方を紹介しました。どれも基本的なことですが、参考にしていただければ幸いです。 開発中のエラーには苦しめられることも多いですが、エラーを自力で解消できた時は跳びあがるくらいうれしいです。これからもエラーと戦いながらレベルアップしていきたいと思います！
