Bug 65408

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

Looks like the MappingData fields need to be either final or volatile.

Is it possible to re-test with JRE 8.latest? Your version is quite old. How reproducible is this error?

(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!

(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!

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...

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.

(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)
.....

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.

(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!!

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.

(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!!

(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.

Several further months have passed with no further information provided. I am therefore resolving this as WORKSFORME.

If, and only if, you are able to provide a test case that demonstrates this issue, feel free to re-open this issue and provide the test case.

Some update on this topic. We use the tomcat embeddded version 8.5.x
Since a while we faced the same issue. We see NullPointer exceptions when working on the response object and java.lang.AssertionErrors when a new request arrives.

We then finally drilled the issue down to a misconfiguration in our ThreadPoolExecutor. There the Linkedblocking queue to store the processor requests in was too small. 
When the queue is too small and the executor is out of threads, any new request is rejected with an RejectedExecutionException.

This execption is handled in the tomcat and cancelledKey is executed which recycles the assigned processor. (See stack below)
And here seems there is an issue in the tomcat code somewhere. It happens that the call of cancelledKeys recycles a processor which is currently in use. This explains the NullPointer we get when sending the response. The processor was recycled while we are working on. That is why we are no longer able to send the response.
But there is also another issue. When we call cancelledKey while the processor is still in work the processor ends finally twice in the recycledProcessor stack. We have seen that in the log that the same processor was pushed twice to the recycledStack without a pop in between.
Also a heap dump showed that the recycledProcessor stack was filled with the same processor object.

Having the same processor more then once on the recycled stack brings us then to the AssertionError. When we have two therads getting the same processor out of the stack we will get the AssertionError.

We fixed the issue with increasing the queue size for the Executor. However maybe the processor handling should reviewed regarding the cancelledKey event and pushing the same object more the once to the stack.

The relevant stacks are

2022-02-08T16:33:25.113+0000 WARN Executor rejected socket for processing
java.util.concurrent.RejectedExecutionException: Task org.apache.tomcat.util.net.NioEndpoint$SocketProcessor@10842846 rejected from c.s.ListenerThreadPoolExecutor@4d77f359[Running, pool size = 250, active threads = 130, queued tasks = 247, completed tasks = 27887]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:1105) ~[?:?]
at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:896) ~[?:?]
at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:872) ~[?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]


2022-02-08T16:33:25.117+0000 INFO HTTP Listener Encountered a non-recycled request and recycled it forcedly.
org.apache.catalina.connector.CoyoteAdapter$RecycleRequiredException: null
at org.apache.catalina.connector.CoyoteAdapter.checkRecycled(CoyoteAdapter.java:546) ~[?:?]
at org.apache.coyote.http11.Http11Processor.recycle(Http11Processor.java:1578) ~[?:?]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1021) ~[?:?]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.release(AbstractProtocol.java:1054) ~[?:?]
at org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:769) ~[?:?]
at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:906) ~[?:?]
at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:872) ~[?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]

REOPENING, as Comment 15 has some reproduction recipe that can be triaged.

(In reply to Thomas Sartissohn from comment #15)
> Some update on this topic. We use the tomcat embeddded version 8.5.x


Thomas, do you know what exact version of 8.5.x you use?
(What is the value of 'x'?)

The version number should be visible in a META-INF/MANIFEST.MF file as the value of 'Implementation-Version' header, or in the org/apache/catalina/util/ServerInfo.properties file.

We face the issue with 8.5.66 and 8.5.75

(In reply to Thomas Sartissohn from comment #17)
> We face the issue with 8.5.66 and 8.5.75


1、From the perspective of this exception scenario, it only occurs when HTTP and websocket exist at the same time, only HTTP is normal. I suspect that excuteor may have a common similar request session when executing HTTP and websocket, resulting in being recycled twice. But I have no way to reproduce the trigger scene, maybe just a guess.


2、Is executor recycling asynchronous? Increasing the queue size for the executor and adding excuter recycling verification  may have some effects. But It may need to reproduce the scene and trials.


3、Will there be optimization in subsequent versions?


Thank for your reply !!!

*** Bug 65755 has been marked as a duplicate of this bug. ***

I've finally managed to track down the root cause of this.

If an application attempts to send a WebSocket message concurrently with the WwebSocket connection closing, it is possible that the application will continue to use the socket after it has been closed. Because some objects associated with the socket are pooled, this could cause problems.

This has been fixed in 8.5.x for 8.5.76 onwards.

The fix required back-porting a lot of changes to the connectors. Users that implement their own Endpoints might see a compatibility issue due to these changes. We will look at options to fix these compatibility issues on a case by case basis as they are identified.