深刻Spring Boot--使用Arthas排查应用404/401问题

背景

在Java Web/Spring Boot开发时，很常见的问题是：

• 网页访问404了，为何访问不到？
• 登录失败了，请求返回401，究竟是哪一个Filter拦截了个人请求？

碰到这种问题时，一般很头痛，特别是在线上环境时。

本文介绍使用Alibaba开源的Java诊断利器Arthas，来快速定位这类Web请求404/401问题。

• github.com/alibaba/art…

Java Web里一个请求被处理的流程

在进入正题以前，先温习下知识。一个普通的Java Web请求处理流程大概是这样子的：

Request  -> Filter1 -> Filter2 ... -> Servlet
                                        |
Response <- Filter1 <- Filter2 ... <- Servlet
复制代码

Demo

本文的介绍基于一个很简单的Demo：github.com/hengyunabc/…

• 访问 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
{"timestamp":1546790485831,"status":404,"error":"Not Found","message":"No message available","path":"/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请求细节

连接

• github.com/alibaba/art…
• alibaba.github.io/arthas/trac…

打个广告，Arthas正在征集使用者，您的使用是对咱们最大的支持。 若是Arthas对您排查问题有帮助，请到这个Issue登记下，并在30分钟内成为Arthas Contributor：

github.com/alibaba/art…