Java异常堆栈丢失仅剩一行

一、问题描述

今日在测试环境帮研发定位问题时,查看日志,发现异常信息丢失,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
2021-12-16 14:05:27[ http-nio-8082-exec-10:519172801 ] - [WARN ] com.xxx.xxx.XxxFilter-doFilter:107 - 解析Tenant出错, 错误信息:Request processing failed; nested exception is java.lang.NullPointerException
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is java.lang.NullPointerException
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:982)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
Caused by: java.lang.NullPointerException

Caused by: java.lang.NullPointerException之后的异常丢失了。

二、异常信息丢失原因

1)Java Doc

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
public class Throwable implements Serializable {
/**
* Provides programmatic access to the stack trace information printed by
* {@link #printStackTrace()}. Returns an array of stack trace elements,
* each representing one stack frame. The zeroth element of the array
* (assuming the array's length is non-zero) represents the top of the
* stack, which is the last method invocation in the sequence. Typically,
* this is the point at which this throwable was created and thrown.
* The last element of the array (assuming the array's length is non-zero)
* represents the bottom of the stack, which is the first method invocation
* in the sequence.
*
* <p>Some virtual machines may, under some circumstances, omit one
* or more stack frames from the stack trace. In the extreme case,
* a virtual machine that has no stack trace information concerning
* this throwable is permitted to return a zero-length array from this
* method. Generally speaking, the array returned by this method will
* contain one element for every frame that would be printed by
* {@code printStackTrace}. Writes to the returned array do not
* affect future calls to this method.
*
* @return an array of stack trace elements representing the stack trace
* pertaining to this throwable.
* @since 1.4
*/
public StackTraceElement[] getStackTrace() {
return getOurStackTrace().clone();
}

}

Throwbable#getStackTrace注释中指出Some virtual machines may, under some circumstances, omit one or more stack frames from the stack trace. In the extreme case, a virtual machine that has no stack trace information concerning this throwable is permitted to return a zero-length array from this method. Generally speaking, the array returned by this method will contain one element for every frame that would be printed by printStackTrace. Writes to the returned array do not affect future calls to this method.

2)JVM性能优化OmitStackTraceInFastThrow参数

https://forum.cuba-platform.com/t/nullpointerexception-being-seen-but-no-stack-trace/6261/3

Missing stack trace is a JVM optimization for frequently repeated exceptions.
You can disable it by adding -XX:-OmitStackTraceInFastThrow to setenv.sh (setenv.bat) file.

也就是说,JDK为了性能会忽略频繁重复出现的异常堆栈,但是可以通过参数-XX:-OmitStackTraceInFastThrow禁用此优化,注意前面有个-

三、验证

查看更广时间范围的日志后,确实发现了完整的NPE堆栈。

# 参考

  1. https://stackoverflow.com/questions/2411487/nullpointerexception-in-java-with-no-stacktrace
  2. https://forum.cuba-platform.com/t/nullpointerexception-being-seen-but-no-stack-trace/6261
  3. https://stackoverflow.com/questions/58696093/when-does-jvm-start-to-omit-stack-traces
  4. https://yoshihisaonoue.wordpress.com/2021/02/07/jvm-option-xx-omitstacktraceinfastthrow/

评论