深入Spring Boot--使用Arthas排查Spring Boot應用404/401問題
背景
在Java Web/Spring Boot開發時，很常見的問題是：
- 網頁訪問404了，為什麼訪問不到？
- 登陸失敗了，請求返回401，到底是哪個Filter攔截了我的請求？
碰到這種問題時，通常很頭痛，特別是在線上環境時。
本文介紹使用Alibaba開源的Java診斷利器Arthas，來快速定位這類Web請求404/401問題。
Java Web裡一個請求被處理的流程
在進入正題之前，先溫習下知識。一個普通的Java Web請求處理流程大概是這樣子的：
Request -> Filter1 -> Filter2 ... -> Servlet | Response <- Filter1 <- Filter2 ... <- Servlet
Demo
本文的介紹基於一個很簡單的Demo：https://github.com/hengyunabc/spring-boot-inside/tree/master/demo-404-401
- 訪問 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：
$ curl http://localhost:8080/a.txt
{ 我們知道一個HTTP Request，大部分情況下都是由一個Servlet處理的，那麼到底是哪個Servlet返回了404？
我們使用Arthas的trace命令來定位：
$ 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會打印出整個請求樹，完整的輸出太長，這裡只擷取關鍵的一輸出：
+---[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的配置就可以了。
這個神奇的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處理的。
總結
- 通過trace Servlet/Filter，可以快速定位Java Web問題
- trace是瞭解應用執行流程的利器，只要trace到關鍵的介面或者類上
- 仔細觀察trace的結果，可以學習到Spring MVC是處理Web請求細節
連結
打個廣告，Arthas正在徵集使用者，您的使用是對我們最大的支援。
如果Arthas對您排查問題有幫助，請到這個Issue登記下，並在30分鐘內成為Arthas Contributor：
https://github.com/alibaba/arthas/issues/395
公眾號
歡迎關注公眾號：橫雲斷嶺的專欄，專注分享Java，Spring Boot，Arthas，Dubbo。
