|
| 1 | +## 背景 |
| 2 | + |
| 3 | +在Java Web/Spring Boot开发时,很常见的问题是: |
| 4 | + |
| 5 | +* 网页访问404了,为什么访问不到? |
| 6 | +* 登陆失败了,请求返回401,到底是哪个Filter拦截了我的请求? |
| 7 | + |
| 8 | +碰到这种问题时,通常很头痛,特别是在线上环境时。 |
| 9 | + |
| 10 | +本文介绍使用Alibaba开源的Java诊断利器Arthas,来快速定位这类Web请求404/401问题。 |
| 11 | + |
| 12 | +* https://github.com/alibaba/arthas |
| 13 | + |
| 14 | +## Java Web里一个请求被处理的流程 |
| 15 | + |
| 16 | +在进入正题之前,先温习下知识。一个普通的Java Web请求处理流程大概是这样子的: |
| 17 | + |
| 18 | +``` |
| 19 | +Request -> Filter1 -> Filter2 ... -> Servlet |
| 20 | + | |
| 21 | +Response <- Filter1 <- Filter2 ... <- Servlet |
| 22 | +``` |
| 23 | + |
| 24 | +## Demo |
| 25 | + |
| 26 | +本文的介绍基于一个很简单的Demo:https://github.com/hengyunabc/spring-boot-inside/tree/master/demo-404-401 |
| 27 | + |
| 28 | +* 访问 http://localhost:8080/ ,返回200,正常打印Welconme信息 |
| 29 | +* 访问 http://localhost:8080/a.txt ,返回404 |
| 30 | +* 访问 http://localhost:8080/admin ,返回401 |
| 31 | + |
| 32 | +## 是哪个Servlet返回了404? |
| 33 | + |
| 34 | +Demo启动后,访问:http://localhost:8080/a.txt ,返回404: |
| 35 | + |
| 36 | +```bash |
| 37 | +$ curl http://localhost:8080/a.txt |
| 38 | +{"timestamp":1546790485831,"status":404,"error":"Not Found","message":"No message available","path":"/a.txt"} |
| 39 | +``` |
| 40 | + |
| 41 | +**我们知道一个HTTP Request,大部分情况下都是由一个Servlet处理的,那么到底是哪个Servlet返回了404?** |
| 42 | + |
| 43 | +我们使用Arthas的`trace`命令来定位: |
| 44 | + |
| 45 | +```bash |
| 46 | +$ trace javax.servlet.Servlet * |
| 47 | +Press Ctrl+C to abort. |
| 48 | +Affect(class-cnt:7 , method-cnt:185) cost in 1018 ms. |
| 49 | +``` |
| 50 | + |
| 51 | +然后访问 http://localhost:8080/a.txt ,Arthas会打印出整个请求树,完整的输出太长,这里只截取关键的一输出: |
| 52 | + |
| 53 | +```java |
| 54 | ++---[13.087083ms] org.springframework.web.servlet.DispatcherServlet:resolveViewName() |
| 55 | +| `---[13.020984ms] org.springframework.web.servlet.DispatcherServlet:resolveViewName() |
| 56 | +| +---[0.002777ms] java.util.List:iterator() |
| 57 | +| +---[0.001955ms] java.util.Iterator:hasNext() |
| 58 | +| +---[0.001739ms] java.util.Iterator:next() |
| 59 | +| `---[12.891979ms] org.springframework.web.servlet.ViewResolver:resolveViewName() |
| 60 | +| +---[0.089811ms] javax.servlet.GenericServlet:<init>() |
| 61 | +| +---[min=0.037696ms,max=0.054478ms,total=0.092174ms,count=2] org.springframework.web.servlet.view.freemarker.FreeMarkerView$GenericServletAdapter:<init>() |
| 62 | +``` |
| 63 | + |
| 64 | +可以看出请求经过Spring MVC的`DispatcherServlet`处理,最终由`ViewResolver`分派给`FreeMarkerView$GenericServletAdapter`处理。所以我们可以知道这个请求最终是被`FreeMarker`处理的。 |
| 65 | +后面再排查`FreeMarker`的配置就可以了。 |
| 66 | + |
| 67 | +这个神奇的`trace javax.servlet.Servlet *`到底是怎样工作的呢? |
| 68 | + |
| 69 | +实际上Arthas会匹配到JVM里所有实现了`javax.servlet.Servlet`的类,然后`trace`它们的所有函数,所以HTTP请求会被打印出来。 |
| 70 | + |
| 71 | +> 这里留一个小问题,为什么只访问了`http://localhost:8080/a.txt`,但Arthas的`trace`命令打印出了两个请求树? |
| 72 | +
|
| 73 | +## 是哪个Filter返回了401? |
| 74 | + |
| 75 | +在Demo里,访问 http://localhost:8080/admin ,会返回401,即没有权限。那么是哪个Filter拦截了请求? |
| 76 | + |
| 77 | +```bash |
| 78 | +$ curl http://localhost:8080/admin |
| 79 | +{"timestamp":1546794743674,"status":401,"error":"Unauthorized","message":"admin filter error.","path":"/admin"} |
| 80 | +``` |
| 81 | + |
| 82 | +我们还是使用Arthas的`trace`命令来定位,不过这次`trace`的是`javax.servlet.Filter`: |
| 83 | + |
| 84 | +```bash |
| 85 | +$ trace javax.servlet.Filter * |
| 86 | +Press Ctrl+C to abort. |
| 87 | +Affect(class-cnt:13 , method-cnt:75) cost in 278 ms. |
| 88 | +``` |
| 89 | + |
| 90 | +再次访问admin,在Arthas里,把整个请求经过哪些Filter处理,都打印为树。这里截取关键部分: |
| 91 | + |
| 92 | +```java |
| 93 | ++---[0.704625ms] org.springframework.web.filter.OncePerRequestFilter:doFilterInternal() |
| 94 | +| `---[0.60387ms] org.springframework.web.filter.RequestContextFilter:doFilterInternal() |
| 95 | +| +---[0.022704ms] org.springframework.web.context.request.ServletRequestAttributes:<init>() |
| 96 | +| +---[0.217636ms] org.springframework.web.filter.RequestContextFilter:initContextHolders() |
| 97 | +| | `---[0.180323ms] org.springframework.web.filter.RequestContextFilter:initContextHolders() |
| 98 | +| | +---[0.034656ms] javax.servlet.http.HttpServletRequest:getLocale() |
| 99 | +| | +---[0.0311ms] org.springframework.context.i18n.LocaleContextHolder:setLocale() |
| 100 | +| | +---[0.008691ms] org.springframework.web.context.request.RequestContextHolder:setRequestAttributes() |
| 101 | +| | `---[0.014918ms] org.apache.commons.logging.Log:isDebugEnabled() |
| 102 | +| +---[0.215481ms] javax.servlet.FilterChain:doFilter() |
| 103 | +| | `---[0.072186ms] com.example.demo404401.AdminFilterConfig$AdminFilter:doFilter() |
| 104 | +| | `---[0.021945ms] javax.servlet.http.HttpServletResponse:sendError() |
| 105 | +``` |
| 106 | + |
| 107 | +可以看到HTTP Request最终是被`com.example.demo404401.AdminFilterConfig$AdminFilter`处理的。 |
| 108 | + |
| 109 | + |
| 110 | +## 总结 |
| 111 | + |
| 112 | +* 通过trace Servlet/Filter,可以快速定位Java Web问题 |
| 113 | +* trace是了解应用执行流程的利器,只要trace到关键的接口或者类上 |
| 114 | +* 仔细观察trace的结果,可以学习到Spring MVC是处理Web请求细节 |
| 115 | + |
| 116 | +## 链接 |
| 117 | + |
| 118 | +* https://github.com/alibaba/arthas |
| 119 | +* https://alibaba.github.io/arthas/trace.html |
| 120 | + |
| 121 | +打个广告,Arthas正在征集使用者,您的使用是对我们最大的支持。 |
| 122 | +如果Arthas对您排找问题有帮助,请到这里来登记下,并在30分钟内成为Arthas Contributor: |
| 123 | + |
| 124 | +https://github.com/alibaba/arthas/issues/395 |
0 commit comments