Arthas實踐--快速排查Spring Boot應用404/401問題

時間 2019-11-12

標籤 arthas 實踐快速排查 spring boot 應用問題欄目 Spring 简体版

原文原文鏈接

背景

在Java Web/Spring Boot開發時，很常見的問題是：html

網頁訪問404了，爲何訪問不到？
登錄失敗了，請求返回401，究竟是哪一個Filter攔截了個人請求？

碰到這種問題時，一般很頭痛，特別是在線上環境時。java

本文介紹使用Alibaba開源的Java診斷利器Arthas，來快速定位這類Web請求404/401問題。git

Java Web裏一個請求被處理的流程

在進入正題以前，先溫習下知識。一個普通的Java Web請求處理流程大概是這樣子的：github

Request  -> Filter1 -> Filter2 ... -> Servlet
                                        |
Response <- Filter1 <- Filter2 ... <- Servlet

Demo

本文的介紹基於一個很簡單的Demo：https://github.com/hengyunabc/spring-boot-inside/tree/master/demo-404-401web

訪問 http://localhost:8080/ ，返回200，正常打印Welconme信息
訪問 http://localhost:8080/a.txt ，返回404
訪問 http://localhost:8080/admin ，返回401

是哪一個Servlet返回了404？

Demo啓動後，訪問：http://localhost:8080/a.txt ，返回404：spring

$ curl http://localhost:8080/a.txt
{"timestamp":1546790485831,"status":404,"error":"Not Found","message":"No message available","path":"/a.txt"}

咱們知道一個HTTP Request，大部分狀況下都是由一個Servlet處理的，那麼究竟是哪一個Servlet返回了404？apache

咱們使用Arthas的trace命令來定位：bash

$ trace javax.servlet.Servlet *
Press Ctrl+C to abort.
Affect(class-cnt:7 , method-cnt:185) cost in 1018 ms.

而後訪問 http://localhost:8080/a.txt ，Arthas會打印出整個請求樹，完整的輸出太長，這裏只截取關鍵的一輸出：curl

+---[13.087083ms] org.springframework.web.servlet.DispatcherServlet:resolveViewName()
|   `---[13.020984ms] org.springframework.web.servlet.DispatcherServlet:resolveViewName()
|       +---[0.002777ms] java.util.List:iterator()
|       +---[0.001955ms] java.util.Iterator:hasNext()
|       +---[0.001739ms] java.util.Iterator:next()
|       `---[12.891979ms] org.springframework.web.servlet.ViewResolver:resolveViewName()
|           +---[0.089811ms] javax.servlet.GenericServlet:<init>()
|           +---[min=0.037696ms,max=0.054478ms,total=0.092174ms,count=2] org.springframework.web.servlet.view.freemarker.FreeMarkerView$GenericServletAdapter:<init>()

能夠看出請求通過Spring MVC的DispatcherServlet處理，最終由ViewResolver分派給FreeMarkerView$GenericServletAdapter處理。因此咱們能夠知道這個請求最終是被FreeMarker處理的。後面再排查FreeMarker的配置就能夠了。ide

這個神奇的trace javax.servlet.Servlet *究竟是怎樣工做的呢？

實際上Arthas會匹配到JVM裏全部實現了javax.servlet.Servlet的類，而後trace它們的全部函數，因此HTTP請求會被打印出來。

這裏留一個小問題，爲何只訪問了http://localhost:8080/a.txt，但Arthas的trace命令打印出了兩個請求樹？

是哪一個Filter返回了401？

在Demo裏，訪問 http://localhost:8080/admin ，會返回401，即沒有權限。那麼是哪一個Filter攔截了請求？

$ curl http://localhost:8080/admin
{"timestamp":1546794743674,"status":401,"error":"Unauthorized","message":"admin filter error.","path":"/admin"}

咱們仍是使用Arthas的trace命令來定位，不過此次trace的是javax.servlet.Filter：

$ trace javax.servlet.Filter *
Press Ctrl+C to abort.
Affect(class-cnt:13 , method-cnt:75) cost in 278 ms.

再次訪問admin，在Arthas裏，把整個請求通過哪些Filter處理，都打印爲樹。這裏截取關鍵部分：

+---[0.704625ms] org.springframework.web.filter.OncePerRequestFilter:doFilterInternal()
|   `---[0.60387ms] org.springframework.web.filter.RequestContextFilter:doFilterInternal()
|       +---[0.022704ms] org.springframework.web.context.request.ServletRequestAttributes:<init>()
|       +---[0.217636ms] org.springframework.web.filter.RequestContextFilter:initContextHolders()
|       |   `---[0.180323ms] org.springframework.web.filter.RequestContextFilter:initContextHolders()
|       |       +---[0.034656ms] javax.servlet.http.HttpServletRequest:getLocale()
|       |       +---[0.0311ms] org.springframework.context.i18n.LocaleContextHolder:setLocale()
|       |       +---[0.008691ms] org.springframework.web.context.request.RequestContextHolder:setRequestAttributes()
|       |       `---[0.014918ms] org.apache.commons.logging.Log:isDebugEnabled()
|       +---[0.215481ms] javax.servlet.FilterChain:doFilter()
|       |   `---[0.072186ms] com.example.demo404401.AdminFilterConfig$AdminFilter:doFilter()
|       |       `---[0.021945ms] javax.servlet.http.HttpServletResponse:sendError()

能夠看到HTTP Request最終是被com.example.demo404401.AdminFilterConfig$AdminFilter處理的。