Bug 65408 - tomcat8.5.X occurs an AssertionError occationally after running for a period of time
Summary: tomcat8.5.X occurs an AssertionError occationally after running for a period ...
Status: NEEDINFO
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.5.x-trunk
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-06-30 07:05 UTC by jiangyangyang
Modified: 2021-08-06 10:00 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description jiangyangyang 2021-06-30 07:05:00 UTC
Tomcat Version:8.5.X  -- 8.5.64
JDK:  Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
OS: CentOS Linux release 7.4.1708 (Core) 
Problem phenomen:  websocket requests failed after running for a period of time

Error report:
AssertionError and NullPointerException  are in the same time, tomcat8.5.64 has problem running in APR or NIO tomcat mode! 




<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor service
<D1><CF><D6><D8>: <B4><ED><CE><F3><B5>Ĵ<A6><C0><ED><C7><EB><C7><F3>
java.lang.AssertionError
        at org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:744)
        at org.apache.catalina.mapper.Mapper.map(Mapper.java:702)
        at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:714)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:358)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
        at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2045)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)




[2021-04-28 09:30:13.369] http-apr-0.0.0.0-31998-exec-21 [ERROR] ErrorPageFilter#forwardToErrorPage(190)Forwarding to error page from request [null] due to exception [null] 
java.lang.NullPointerException: null
<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.catalina.core.StandardWrapperValve invoke
<D1><CF><D6><D8>: <D4><DA>·<BE><B6>Ϊ[/ctl]<B5><C4><C9><CF><CF><C2><CE><C4><D6>У<AC>servlet[dispatcherServlet]<B5><C4>Servlet.service()<D2><FD><B7><A2><D2>쳣
java.lang.NullPointerException
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.forwardToErrorPage(ErrorPageFilter.java:197)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.handleException(ErrorPageFilter.java:180)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:145)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:105)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:123)
        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:200)
        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:200)
        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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:698)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:364)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
        at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2045)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor service
<D1><CF><D6><D8>: <B4><ED><CE><F3><B5>Ĵ<A6><C0><ED><C7><EB><C7><F3>
java.lang.NullPointerException

<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor endRequest
<D1><CF><D6><D8>: <B4><ED><CE><F3><CD><EA><B3><C9><CF><E0>Ӧ
java.lang.NullPointerException
Comment 1 jiangyangyang 2021-06-30 07:47:02 UTC
Tomcat Version:8.5.X  -- 8.5.64
JDK:  Java(TM) SE Runtime Environment (build 1.8.0_66-b17)
OS: CentOS Linux release 7.4.1708 (Core) 
Problem phenomen:  websocket  requests occationally failed after running for a period of time
CPU/MEM status: CPU used 9.6% ; Mem used 54.7% ; JVM Heap used 54.7%

Error report:
AssertionError and NullPointerException occationally are in the same time , tomcat8.5.64 has problem running in APR or NIO tomcat mode! 




<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor service
<D1><CF><D6><D8>: <B4><ED><CE><F3><B5>Ĵ<A6><C0><ED><C7><EB><C7><F3>
java.lang.AssertionError
        at org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:744)
        at org.apache.catalina.mapper.Mapper.map(Mapper.java:702)
        at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:714)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:358)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
        at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2045)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)




[2021-04-28 09:30:13.369] http-apr-0.0.0.0-31998-exec-21 [ERROR] ErrorPageFilter#forwardToErrorPage(190)Forwarding to error page from request [null] due to exception [null] 
java.lang.NullPointerException: null
<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.catalina.core.StandardWrapperValve invoke
<D1><CF><D6><D8>: <D4><DA>·<BE><B6>Ϊ[/ctl]<B5><C4><C9><CF><CF><C2><CE><C4><D6>У<AC>servlet[dispatcherServlet]<B5><C4>Servlet.service()<D2><FD><B7><A2><D2>쳣
java.lang.NullPointerException
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.forwardToErrorPage(ErrorPageFilter.java:197)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.handleException(ErrorPageFilter.java:180)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:145)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:105)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:123)
        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:200)
        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:200)
        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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:698)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:364)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831)
        at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2045)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor service
<D1><CF><D6><D8>: <B4><ED><CE><F3><B5>Ĵ<A6><C0><ED><C7><EB><C7><F3>
java.lang.NullPointerException

<CB><C4><D4><C2> 28, 2021 9:30:13 <C9><CF><CE><E7> org.apache.coyote.http11.Http11Processor endRequest
<D1><CF><D6><D8>: <B4><ED><CE><F3><CD><EA><B3><C9><CF><E0>Ӧ
java.lang.NullPointerException
Comment 2 Mark Thomas 2021-06-30 09:43:23 UTC
Looks like the MappingData fields need to be either final or volatile.
Comment 3 Christopher Schultz 2021-07-01 16:39:49 UTC
Is it possible to re-test with JRE 8.latest? Your version is quite old. How reproducible is this error?
Comment 4 jiangyangyang 2021-07-05 02:30:39 UTC
(In reply to Mark Thomas from comment #2)
> Looks like the MappingData fields need to be either final or volatile.

Maybe, there are no errors in my application self, so I can not find which variablr or parameter is null or lost in this occasional sences.And the access logs are niarmal, no url parameteters are missing!
Comment 5 jiangyangyang 2021-07-05 02:36:39 UTC
(In reply to Christopher Schultz from comment #3)
> Is it possible to re-test with JRE 8.latest? Your version is quite old. How
> reproducible is this error?

JRE 1.8.0_66 is our mainstream jdk version, the assertionError is only found when we using websocket protocol, not found in the http protocol!
Comment 6 jiangyangyang 2021-07-06 10:08:02 UTC
It occurs  the error "1970-01-01      07:59:59        0.000   -       -       null    30.78.12.210    500     null    null    null   " at the same time with the  AssertionError...
Comment 7 Mark Thomas 2021-07-06 11:00:17 UTC
The original report states that WebSocket requests fail. However, the stack traces shown are for HTTP requests.

How do WebSocket requests fail. Are there stack traces associated with these failures? If so, what are they.
Comment 8 jiangyangyang 2021-07-07 10:29:00 UTC
(In reply to Mark Thomas from comment #7)
> The original report states that WebSocket requests fail. However, the stack
> traces shown are for HTTP requests.
> 
> How do WebSocket requests fail. Are there stack traces associated with these
> failures? If so, what are they.

Supplement:

At present, we have found that there are such problems in the two application environment which common websocket and http, both of which use websocket with no errors,but only http has error 500 . There are no missing parameters in the corresponding code of 500 requests in the access log.



Difficult:

It is hard to obtain the thread dump of exception thead, due to the corresponding request error quickly within 200 millisecond.


Investigation progress:

We found some differents after comparing the error report with the normal call relationship:

-------  normal  --------
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:130)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:105)
......


-------  abnormal  --------

 at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:105)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:123)
        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:200)
.....
Comment 9 Mark Thomas 2021-07-19 14:07:03 UTC
Both the stack traces in the bug description are consistent with attempting to use a request object that has already been recycled. While that might be a Tomcat bug, it is typically cased by applications retaining references to requests, responses etc and attempting to use the objects after they are no longer valid.

Unless a test case is provided that can be used to recreate this bug, it will eventually get resolved as WORKSFORME.
Comment 10 jiangyangyang 2021-08-06 07:52:30 UTC
(In reply to Mark Thomas from comment #9)
> Both the stack traces in the bug description are consistent with attempting
> to use a request object that has already been recycled. While that might be
> a Tomcat bug, it is typically cased by applications retaining references to
> requests, responses etc and attempting to use the objects after they are no
> longer valid.
> 
> Unless a test case is provided that can be used to recreate this bug, it
> will eventually get resolved as WORKSFORME.


At present, we have four application clusters that both use websocket and http have AssertionError! But we did not find the inevitable scene.It does not reache the application logic when the 500 AssertionError occured in the catalina.out. And we can not prove application used a request object that has already been recycled or memory cache recycle failed.

1. What is the purpose of this code, can it be cancelled ?

739    if (mappingData.host != null) {
744            throw new AssertionError();
        }

2.Which debug logs should be added to tomcat,and how to do it?

3.Why does the http method of OPTION requests also have AssertionError and 500 ? 



Thanks for your reply!!
Comment 11 Mark Thomas 2021-08-06 08:03:24 UTC
1. It is there as a safety check. mappingData.host should never be null. No, it won't be removed. That would just move the problem somewhere else, potentially less obvious.

2. https://cwiki.apache.org/confluence/display/TOMCAT/Troubleshooting+and+Diagnostics#TroubleshootingandDiagnostics-TroubleshootingunexpectedResponsestateproblems

3. Because it is handled by a Servlet just like all other requests.
Comment 12 jiangyangyang 2021-08-06 09:40:04 UTC
(In reply to Mark Thomas from comment #11)
> 1. It is there as a safety check. mappingData.host should never be null. No,
> it won't be removed. That would just move the problem somewhere else,
> potentially less obvious.
> 
> 2.
> https://cwiki.apache.org/confluence/display/TOMCAT/
> Troubleshooting+and+Diagnostics#TroubleshootingandDiagnostics-
> TroubleshootingunexpectedResponsestateproblems
> 
> 3. Because it is handled by a Servlet just like all other requests.



We have tried debugging in Idea Tool, but mappingData.host is null when test request is normal.

When the mappingData.host is been assigment and when to be recycled ?


Thank for your reply!!
Comment 13 Mark Thomas 2021-08-06 10:00:21 UTC
(In reply to jiangyangyang from comment #12)
> We have tried debugging in Idea Tool, but mappingData.host is null when test
> request is normal.

Which is a typical symptom of an application retaining a reference to a response after it should.

We have provided information on how to debug this with RECYCLE_FACADES.

> When the mappingData.host is been assignment and when to be recycled ?

You have the source code. You can answer this question yourself.