背景
在 Java web/Spring Boot 开发时, 很常见的问题是:
网页访问 404 了, 为什么访问不到?
登陆失败了, 请求返回 401, 到底是哪个 Filter 拦截了我的请求?
碰到这种问题时, 通常很头痛, 特别是在线上环境时.
本文介绍使用 Alibaba 开源的 Java 诊断利器 Arthas, 来快速定位这类 Web 请求 404/401 问题.
https://github.com/alibaba/arthas
Java Web 里一个请求被处理的流程
在进入正题之前, 先温习下知识. 一个普通的 Java Web 请求处理流程大概是这样子的:
- Request -> Filter1 -> Filter2 ... -> Servlet
- |
- Response <- Filter1 <- Filter2 ... <- Servlet
Demo
本文的介绍基于一个很简单的 Demo:
访问 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 请求细节
链接
- https://github.com/alibaba/arthas
- https://alibaba.github.io/arthas/trace.html
打个广告, Arthas 正在征集使用者, 您的使用是对我们最大的支持. 如果 Arthas 对您排查问题有帮助, 请到这个 Issue 登记下, 并在 30 分钟内成为 Arthas Contributor:
https://github.com/alibaba/arthas/issues/395
来源: https://juejin.im/post/5c32cdba6fb9a049ed310633