はじめに

Spring学習の一環として、Webアプリケーションのログを出力したところ、DispatcherServletをはじめとしたSpringMVCの主要コンポーネントが登場しました。
そこで、ログを１行ずつ追うことで、SpringMVCの大まかな処理フローを理解しました。
学習の記録として、記事にさせていただきます。

なお、誤りや改善の余地がございましたら、優しくご指摘いただけますと幸いです。

前提

本記事では、SpringBootで作成した簡単なWebアプリケーションを使用しています。（こちらの記事を参考に作成しました。）
次のようなコントローラメソッドにアクセスした場合のログについて説明します。

@GetMapping("/")
public String index(Model model) {
	List<Member> members = memberMapper.all();  // ビジネスロジック
	model.addAttribute("members", members);
	return "index"; // Viewを返却
}

クライアントから http://localhost:8080/ にアクセスがあった場合、index(Model model)が呼び出されます。

３行目でビジネスロジックを実行し、4行目でその結果をModelに追加しています。（ただし、これらの処理は、本記事とは直接的な関係はありません。）

５行目で"index"というViewの論理名を返却しています。

ログを出力する

ログレベルをTRACEに変更する

application.propertiesにてログの設定を変更します。（こちらの記事を参考にさせていただきました。）

application.properties

logging.level.web=trace

ロガーレベルを「TRACE」に変更しています。デフォルトでは「INFO」です。

ログを出力させる

http://localhost:8080/ にアクセスし、ログを出力させます。
コンソールに出力されたログは次の通りです。（※このアクセス以前のログは表示していません。）

2024-01-26T13:28:42.810+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet       : GET "/", parameters={}, headers={host:[localhost:8080], connection:[keep-alive], cache-control:[max-age=0], sec-ch-ua:["Not_A Brand";v="8", "Chromium";v="120", "Microsoft Edge";v="120"], sec-ch-ua-mobile:[?0], sec-ch-ua-platform:["Windows"], upgrade-insecure-requests:[1], user-agent:[Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36 Edg/120.0.0.0], accept:[text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7], sec-fetch-site:[none], sec-fetch-mode:[navigate], sec-fetch-user:[?1], sec-fetch-dest:[document], accept-encoding:[gzip, deflate, br], accept-language:[ja,en;q=0.9,en-GB;q=0.8,en-US;q=0.7]} in DispatcherServlet 'dispatcherServlet'
2024-01-26T13:28:42.811+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.search.controllers.MemberController#index(Model)
2024-01-26T13:28:42.811+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.web.method.HandlerMethod            : Arguments: [{}]
2024-01-26T13:28:42.814+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1
2024-01-26T13:28:42.815+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.w.s.v.InternalResourceViewResolver  : View with key [index] served from cache
2024-01-26T13:28:42.815+09:00 DEBUG 13704 --- [nio-8080-exec-6] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8, application/signed-exchange;v=b3;q=0.7]
2024-01-26T13:28:42.815+09:00 TRACE 13704 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet       : Rendering view [org.thymeleaf.spring6.view.ThymeleafView@783d6283] 
2024-01-26T13:28:42.818+09:00 DEBUG 13704 --- [nio-8080-exec-6] o.s.web.servlet.DispatcherServlet       : Completed 200 OK, headers={Content-Type:[text/html;charset=UTF-8], Content-Language:[ja], Transfer-Encoding:[chunked], Date:[Fri, 26 Jan 2024 04:28:42 GMT], Keep-Alive:[timeout=60], Connection:[keep-alive]}

設定を変更した為、TRACEレベルのログが出力されるようになりました。

ログを１行ずつ解読する

出力したログを1行ずつ解読してみます。

なお、以下に示す行単位のログは、記事の見やすさの為に[nio-8080-exec-6]から左の部分を省略しています。

１行目：DispatcherServlet

o.s.web.servlet.DispatcherServlet       : GET "/", parameters={}, headers={host:[localhost:8080], connection:[keep-alive], cache-control:[max-age=0], sec-ch-ua:["Not_A Brand";v="8", "Chromium";v="120", "Microsoft Edge";v="120"], sec-ch-ua-mobile:[?0], sec-ch-ua-platform:["Windows"], upgrade-insecure-requests:[1], user-agent:[Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/120.0.0.0 Safari/537.36 Edg/120.0.0.0], accept:[text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7], sec-fetch-site:[none], sec-fetch-mode:[navigate], sec-fetch-user:[?1], sec-fetch-dest:[document], accept-encoding:[gzip, deflate, br], accept-language:[ja,en;q=0.9,en-GB;q=0.8,en-US;q=0.7]} in DispatcherServlet 'dispatcherServlet'

DispatcherServletは、HTTPリクエストを処理する為の中心的なクラスです。
GETメソッドであること、URLのパス、パラメータ、ヘッダーなど、リクエストの詳細情報が示されています。

２行目：RequestMappingHandlerMapping

o.s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.search.controllers.MemberController#index(Model)

RequestMappingHandlerMappingは、リクエストに対応するコントローラメソッドをマッピングします。ここでは、MemberControllerクラスのindex(Model)メソッドにマッピングしています。

RequestMappingHandlerMappingは、間接的にHandlerMappingインタフェースを実装しています。

３行目：HandlerMethod

o.s.web.method.HandlerMethod            : Arguments: [{}]

HandlerMethodは、処理対象のコントローラメソッドとその引数をカプセル化して管理します。ここでは、index()メソッドが引数なしで呼び出されています。

４行目：RequestMappingHandlerAdapter

o.s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1

は、指定されたハンドラ（HandlerMethod）を呼び出しリクエストを処理します。cacheSeconds=-1でキャッシュを無効にしています。

RequestMappingHandlerAdapterは、HandlerAdapterインタフェースを実装しています。

５行目：InternalResourceViewResolver

o.s.w.s.v.InternalResourceViewResolver  : View with key [index] served from cache

InternalResourceViewResolverは、論理ビュー名（index）を物理ビューに解決します。ここでは、プロジェクトの内部リソース（index.html）からViewインスタンスを生成して提供します。

InternalResourceViewResolverは、間接的にViewResolverインタフェースを実装しています。

６行目：ContentNegotiatingViewResolver

o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8, application/signed-exchange;v=b3;q=0.7]

ContentNegotiatingViewResolverは、リクエストに基づいて最適なビューフォーマットを選択します。ここでは、クライアントがtext/htmlを選択している為、それに基づきフォーマットを選択し、InternalResourceViewResolverが提供するViewをオーバーライドしています。

ContentNegotiatingViewResolverは、ViewResolverインタフェースを実装しています。

７行目：DispatcherServlet

o.s.web.servlet.DispatcherServlet       : Rendering view [org.thymeleaf.spring6.view.ThymeleafView@783d6283]

DispatcherServletは、返却されたビューにレンダリング処理を委譲します。ここでは、Thymeleafを使用してビューを描画しています。

８行目：DispatcherServlet

o.s.web.servlet.DispatcherServlet       : Completed 200 OK, headers={Content-Type:[text/html;charset=UTF-8], Content-Language:[ja], Transfer-Encoding:[chunked], Date:[Fri, 26 Jan 2024 04:28:42 GMT], Keep-Alive:[timeout=60], Connection:[keep-alive]}

DispatcherServletは、リクエスト処理を正常終了した場合、200 OKを返却します。HTTPレスポンスのヘッダー情報が示されています。

処理フローを図にしてみる

ログに登場したSpringMVCの主要コンポーネントを中心に、大まかな処理フローを図で表現しました。（こちらを参考にさせていただきました。）
図中の数字は、ログの行数に対応するようにしています。

DispatcherServletを中心に、各コンポーネントが委譲された処理を実行していることがわかります。

HandlerMethodについては、図でどう表現するものかと大変迷いました。（今も迷っています…）誤りがございましたら、教えていただけますと幸いです。

おわりに

以前から興味のあったDispatcherServletとその関連処理について、ログを１行ずつ追うことで、大まかな処理フローを理解することができました。

今回はシンプルなViewを返却するだけのリクエストということでログもシンプルでしたが、リクエストが複雑になると、ログや処理フローも複雑化するのかな、と思っています。

お読みいただきありがとうございました。この記事が誰かのお役に立つことを祈っております。