V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
hengyunabc
V2EX  ›  Java

Arthas 实践--快速排查 Spring Boot 应用 404/401 问题

  •  
  •   hengyunabc ·
    hengyunabc · 2019-01-07 13:53:06 +08:00 · 1573 次点击
    这是一个创建于 1907 天前的主题,其中的信息可能已经有所发展或是发生改变。

    背景

    在 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
    {"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 请求细节

    链接

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

    https://github.com/alibaba/arthas/issues/395

    公众号: 横云断岭的专栏,专注 Java, Spring Boot, Arthas, Dubbo

    2 条回复    2019-01-17 01:06:25 +08:00
    wl2358
        1
    wl2358  
       2019-01-08 10:09:58 +08:00 via Android
    很赞
    Solace202
        2
    Solace202  
       2019-01-17 01:06:25 +08:00 via Android
    手机 插眼
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   3584 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 23ms · UTC 04:37 · PVG 12:37 · LAX 21:37 · JFK 00:37
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.