You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Rainer Jung <ra...@kippdata.de> on 2024/03/08 20:28:15 UTC
Very sporadic test failures in org.apache.catalina.core.TestAsyncContextImpl for TC 8.5 and 9
Again, this is not a new failure and it happens extremely infrequent.
Observed with JSSE on various Linux distributions and with various JVM
versions and vendors. Only observed for TC 8.5 and 9, but for 10.1 and
11 the unit tests are run with much fewer JVM combinations so I can not
exclude the problem might happen there as well.
This info is not intended to prevent a release.
The typical situation is:
Testcase: testBug49567 took 21.162 sec
FAILED
expected:<...alse2true3true4true5[false]> but
was:<...alse2true3true4true5[]>
junit.framework.AssertionFailedError:
expected:<...alse2true3true4true5[false]> but
was:<...alse2true3true4true5[]>
at
org.apache.catalina.core.TestAsyncContextImpl.testBug49567(TestAsyncContextImpl.java:163)
at
java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
The execution log contains:
22-Feb-2024 11:19:03.617 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testBug49567]
22-Feb-2024 11:19:03.626 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["http-nio-127.0.0.1-auto-11"]
22-Feb-2024 11:19:03.627 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
22-Feb-2024 11:19:03.627 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
engine: [Apache Tomcat/9.0.86]
22-Feb-2024 11:19:03.640 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio-127.0.0.1-auto-11-46529"]
Exception in thread "Thread-9" java.lang.NullPointerException: Cannot
invoke "org.apache.catalina.connector.Request.getCoyoteRequest()"
because "this.request" is null
at
org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
at
org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
at
org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
at
org.apache.catalina.core.TestAsyncContextImpl$Bug49567Servlet$1$1.run(TestAsyncContextImpl.java:383)
at java.base/java.lang.Thread.run(Thread.java:1583)
22-Feb-2024 11:19:24.685 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-127.0.0.1-auto-11-46529"]
22-Feb-2024 11:19:24.693 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
22-Feb-2024 11:19:24.729 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio-127.0.0.1-auto-11-46529"]
22-Feb-2024 11:19:24.739 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["http-nio-127.0.0.1-auto-11-46529"]
or as a variation:
08-Mar-2024 14:44:59.132 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testBug49528]
08-Mar-2024 14:44:59.141 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["http-nio2-127.0.0.1-auto-10"]
08-Mar-2024 14:44:59.151 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
08-Mar-2024 14:44:59.151 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
engine: [Apache Tomcat/9.0.86sp1]
08-Mar-2024 14:44:59.170 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio2-127.0.0.1-auto-10-37101"]
java.lang.NullPointerException: Cannot invoke
"org.apache.catalina.connector.Request.getCoyoteRequest()" because
"this.request" is null
at
org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
at
org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
at
org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
at
org.apache.catalina.core.TestAsyncContextImpl$Bug49528Servlet$1.run(TestAsyncContextImpl.java:303)
at
org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:543)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
at java.base/java.lang.Thread.run(Thread.java:1583)
08-Mar-2024 14:45:00.196 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-10-37101"]
08-Mar-2024 14:45:00.198 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
08-Mar-2024 14:45:00.217 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio2-127.0.0.1-auto-10-37101"]
08-Mar-2024 14:45:00.219 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["http-nio2-127.0.0.1-auto-10-37101"]
In addition to these failures I also see NullPointerExceptions in other
places and other test cases in TestAsyncContextImpl. Those typically go
unnoticed, because they do not result in a test failure. It seems they
happen during test shutdown, so they might be unrelated and not
important. An example:
17-Jan-2024 15:14:13.604 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-127.0.0.1-auto-44-53668"]
17-Jan-2024 15:14:13.611 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
17-Jan-2024 15:14:13.616 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio-127.0.0.1-auto-44-53668"]
17-Jan-2024 15:14:13.621 SEVERE [http-nio-127.0.0.1-auto-44-exec-1]
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun Error
running socket processor
java.lang.NullPointerException
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1797)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:750)
Exception in thread "http-nio-127.0.0.1-auto-44-exec-1"
java.lang.NullPointerException
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1813)
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:750)
17-Jan-2024 15:14:13.631 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["http-nio-127.0.0.1-auto-44-53668"]
Thanks and regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Very sporadic test failures in org.apache.catalina.core.TestAsyncContextImpl for TC 8.5 and 9
Posted by Rainer Jung <ra...@kippdata.de>.
Thanks again, I will keep an eye on it.
Am 15.03.24 um 20:43 schrieb Mark Thomas:
> On 08/03/2024 20:28, Rainer Jung wrote:
>> Again, this is not a new failure and it happens extremely infrequent.
>> Observed with JSSE on various Linux distributions and with various JVM
>> versions and vendors. Only observed for TC 8.5 and 9, but for 10.1 and
>> 11 the unit tests are run with much fewer JVM combinations so I can
>> not exclude the problem might happen there as well.
>
> Looks like a timing issue when we have a non-container thread still
> accessing the AsyncContext (it shouldn't do that).
>
> The test acknowledged the problem but you found another fisalure mode
> that wasn't handled. It now is. Hopefully, these tests should be more
> reliable going forwards.
>
> Mark
>
>
>>
>> This info is not intended to prevent a release.
>>
>> The typical situation is:
>>
>> Testcase: testBug49567 took 21.162 sec
>> FAILED
>> expected:<...alse2true3true4true5[false]> but
>> was:<...alse2true3true4true5[]>
>> junit.framework.AssertionFailedError:
>> expected:<...alse2true3true4true5[false]> but
>> was:<...alse2true3true4true5[]>
>> at
>> org.apache.catalina.core.TestAsyncContextImpl.testBug49567(TestAsyncContextImpl.java:163)
>> at
>> java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
>>
>> The execution log contains:
>>
>> 22-Feb-2024 11:19:03.617 INFO [main]
>> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
>> [testBug49567]
>> 22-Feb-2024 11:19:03.626 INFO [main]
>> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
>> ["http-nio-127.0.0.1-auto-11"]
>> 22-Feb-2024 11:19:03.627 INFO [main]
>> org.apache.catalina.core.StandardService.startInternal Starting
>> service [Tomcat]
>> 22-Feb-2024 11:19:03.627 INFO [main]
>> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
>> engine: [Apache Tomcat/9.0.86]
>> 22-Feb-2024 11:19:03.640 INFO [main]
>> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
>> ["http-nio-127.0.0.1-auto-11-46529"]
>> Exception in thread "Thread-9" java.lang.NullPointerException: Cannot
>> invoke "org.apache.catalina.connector.Request.getCoyoteRequest()"
>> because "this.request" is null
>> at
>> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
>> at
>> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
>> at
>> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
>> at
>> org.apache.catalina.core.TestAsyncContextImpl$Bug49567Servlet$1$1.run(TestAsyncContextImpl.java:383)
>> at java.base/java.lang.Thread.run(Thread.java:1583)
>> 22-Feb-2024 11:19:24.685 INFO [main]
>> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
>> ["http-nio-127.0.0.1-auto-11-46529"]
>> 22-Feb-2024 11:19:24.693 INFO [main]
>> org.apache.catalina.core.StandardService.stopInternal Stopping service
>> [Tomcat]
>> 22-Feb-2024 11:19:24.729 INFO [main]
>> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
>> ["http-nio-127.0.0.1-auto-11-46529"]
>> 22-Feb-2024 11:19:24.739 INFO [main]
>> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
>> ["http-nio-127.0.0.1-auto-11-46529"]
>>
>>
>> or as a variation:
>>
>> 08-Mar-2024 14:44:59.132 INFO [main]
>> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
>> [testBug49528]
>> 08-Mar-2024 14:44:59.141 INFO [main]
>> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
>> ["http-nio2-127.0.0.1-auto-10"]
>> 08-Mar-2024 14:44:59.151 INFO [main]
>> org.apache.catalina.core.StandardService.startInternal Starting
>> service [Tomcat]
>> 08-Mar-2024 14:44:59.151 INFO [main]
>> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
>> engine: [Apache Tomcat/9.0.86sp1]
>> 08-Mar-2024 14:44:59.170 INFO [main]
>> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
>> ["http-nio2-127.0.0.1-auto-10-37101"]
>> java.lang.NullPointerException: Cannot invoke
>> "org.apache.catalina.connector.Request.getCoyoteRequest()" because
>> "this.request" is null
>> at
>> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
>> at
>> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
>> at
>> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
>> at
>> org.apache.catalina.core.TestAsyncContextImpl$Bug49528Servlet$1.run(TestAsyncContextImpl.java:303)
>> at
>> org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:543)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
>> at
>> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
>> at java.base/java.lang.Thread.run(Thread.java:1583)
>> 08-Mar-2024 14:45:00.196 INFO [main]
>> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
>> ["http-nio2-127.0.0.1-auto-10-37101"]
>> 08-Mar-2024 14:45:00.198 INFO [main]
>> org.apache.catalina.core.StandardService.stopInternal Stopping service
>> [Tomcat]
>> 08-Mar-2024 14:45:00.217 INFO [main]
>> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
>> ["http-nio2-127.0.0.1-auto-10-37101"]
>> 08-Mar-2024 14:45:00.219 INFO [main]
>> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
>> ["http-nio2-127.0.0.1-auto-10-37101"]
>>
>>
>> In addition to these failures I also see NullPointerExceptions in
>> other places and other test cases in TestAsyncContextImpl. Those
>> typically go unnoticed, because they do not result in a test failure.
>> It seems they happen during test shutdown, so they might be unrelated
>> and not important. An example:
>>
>> 17-Jan-2024 15:14:13.604 INFO [main]
>> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
>> ["http-nio-127.0.0.1-auto-44-53668"]
>> 17-Jan-2024 15:14:13.611 INFO [main]
>> org.apache.catalina.core.StandardService.stopInternal Stopping service
>> [Tomcat]
>> 17-Jan-2024 15:14:13.616 INFO [main]
>> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
>> ["http-nio-127.0.0.1-auto-44-53668"]
>> 17-Jan-2024 15:14:13.621 SEVERE [http-nio-127.0.0.1-auto-44-exec-1]
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun Error
>> running socket processor
>> java.lang.NullPointerException
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1797)
>> at
>> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
>> at
>> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>> at java.lang.Thread.run(Thread.java:750)
>> Exception in thread "http-nio-127.0.0.1-auto-44-exec-1"
>> java.lang.NullPointerException
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
>> at
>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1813)
>> at
>> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
>> at
>> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
>> at
>> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
>> at java.lang.Thread.run(Thread.java:750)
>> 17-Jan-2024 15:14:13.631 INFO [main]
>> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
>> ["http-nio-127.0.0.1-auto-44-53668"]
>>
>>
>> Thanks and regards,
>>
>> Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Very sporadic test failures in org.apache.catalina.core.TestAsyncContextImpl for TC 8.5 and 9
Posted by Mark Thomas <ma...@apache.org>.
On 08/03/2024 20:28, Rainer Jung wrote:
> Again, this is not a new failure and it happens extremely infrequent.
> Observed with JSSE on various Linux distributions and with various JVM
> versions and vendors. Only observed for TC 8.5 and 9, but for 10.1 and
> 11 the unit tests are run with much fewer JVM combinations so I can not
> exclude the problem might happen there as well.
Looks like a timing issue when we have a non-container thread still
accessing the AsyncContext (it shouldn't do that).
The test acknowledged the problem but you found another fisalure mode
that wasn't handled. It now is. Hopefully, these tests should be more
reliable going forwards.
Mark
>
> This info is not intended to prevent a release.
>
> The typical situation is:
>
> Testcase: testBug49567 took 21.162 sec
> FAILED
> expected:<...alse2true3true4true5[false]> but
> was:<...alse2true3true4true5[]>
> junit.framework.AssertionFailedError:
> expected:<...alse2true3true4true5[false]> but
> was:<...alse2true3true4true5[]>
> at
> org.apache.catalina.core.TestAsyncContextImpl.testBug49567(TestAsyncContextImpl.java:163)
> at
> java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
>
> The execution log contains:
>
> 22-Feb-2024 11:19:03.617 INFO [main]
> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
> [testBug49567]
> 22-Feb-2024 11:19:03.626 INFO [main]
> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
> ["http-nio-127.0.0.1-auto-11"]
> 22-Feb-2024 11:19:03.627 INFO [main]
> org.apache.catalina.core.StandardService.startInternal Starting service
> [Tomcat]
> 22-Feb-2024 11:19:03.627 INFO [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> engine: [Apache Tomcat/9.0.86]
> 22-Feb-2024 11:19:03.640 INFO [main]
> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> Exception in thread "Thread-9" java.lang.NullPointerException: Cannot
> invoke "org.apache.catalina.connector.Request.getCoyoteRequest()"
> because "this.request" is null
> at
> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
> at
> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
> at
> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
> at
> org.apache.catalina.core.TestAsyncContextImpl$Bug49567Servlet$1$1.run(TestAsyncContextImpl.java:383)
> at java.base/java.lang.Thread.run(Thread.java:1583)
> 22-Feb-2024 11:19:24.685 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> 22-Feb-2024 11:19:24.693 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 22-Feb-2024 11:19:24.729 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> 22-Feb-2024 11:19:24.739 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
>
>
> or as a variation:
>
> 08-Mar-2024 14:44:59.132 INFO [main]
> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
> [testBug49528]
> 08-Mar-2024 14:44:59.141 INFO [main]
> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10"]
> 08-Mar-2024 14:44:59.151 INFO [main]
> org.apache.catalina.core.StandardService.startInternal Starting service
> [Tomcat]
> 08-Mar-2024 14:44:59.151 INFO [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> engine: [Apache Tomcat/9.0.86sp1]
> 08-Mar-2024 14:44:59.170 INFO [main]
> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.Request.getCoyoteRequest()" because
> "this.request" is null
> at
> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
> at
> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
> at
> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
> at
> org.apache.catalina.core.TestAsyncContextImpl$Bug49528Servlet$1.run(TestAsyncContextImpl.java:303)
> at
> org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:543)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
> at java.base/java.lang.Thread.run(Thread.java:1583)
> 08-Mar-2024 14:45:00.196 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> 08-Mar-2024 14:45:00.198 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 08-Mar-2024 14:45:00.217 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> 08-Mar-2024 14:45:00.219 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
>
>
> In addition to these failures I also see NullPointerExceptions in other
> places and other test cases in TestAsyncContextImpl. Those typically go
> unnoticed, because they do not result in a test failure. It seems they
> happen during test shutdown, so they might be unrelated and not
> important. An example:
>
> 17-Jan-2024 15:14:13.604 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
> 17-Jan-2024 15:14:13.611 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 17-Jan-2024 15:14:13.616 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
> 17-Jan-2024 15:14:13.621 SEVERE [http-nio-127.0.0.1-auto-44-exec-1]
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun Error
> running socket processor
> java.lang.NullPointerException
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1797)
> at
> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:750)
> Exception in thread "http-nio-127.0.0.1-auto-44-exec-1"
> java.lang.NullPointerException
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1813)
> at
> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:750)
> 17-Jan-2024 15:14:13.631 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
>
>
> Thanks and regards,
>
> Rainer
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: Very sporadic test failures in org.apache.catalina.core.TestAsyncContextImpl for TC 8.5 and 9
Posted by Rémy Maucherat <re...@apache.org>.
On Fri, Mar 8, 2024 at 9:28 PM Rainer Jung <ra...@kippdata.de> wrote:
>
> Again, this is not a new failure and it happens extremely infrequent.
> Observed with JSSE on various Linux distributions and with various JVM
> versions and vendors. Only observed for TC 8.5 and 9, but for 10.1 and
> 11 the unit tests are run with much fewer JVM combinations so I can not
> exclude the problem might happen there as well.
>
> This info is not intended to prevent a release.
>
> The typical situation is:
>
> Testcase: testBug49567 took 21.162 sec
> FAILED
> expected:<...alse2true3true4true5[false]> but
> was:<...alse2true3true4true5[]>
> junit.framework.AssertionFailedError:
> expected:<...alse2true3true4true5[false]> but
> was:<...alse2true3true4true5[]>
> at
> org.apache.catalina.core.TestAsyncContextImpl.testBug49567(TestAsyncContextImpl.java:163)
> at
> java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
>
> The execution log contains:
>
> 22-Feb-2024 11:19:03.617 INFO [main]
> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
> [testBug49567]
> 22-Feb-2024 11:19:03.626 INFO [main]
> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
> ["http-nio-127.0.0.1-auto-11"]
> 22-Feb-2024 11:19:03.627 INFO [main]
> org.apache.catalina.core.StandardService.startInternal Starting service
> [Tomcat]
> 22-Feb-2024 11:19:03.627 INFO [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> engine: [Apache Tomcat/9.0.86]
> 22-Feb-2024 11:19:03.640 INFO [main]
> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> Exception in thread "Thread-9" java.lang.NullPointerException: Cannot
> invoke "org.apache.catalina.connector.Request.getCoyoteRequest()"
> because "this.request" is null
> at
> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
> at
> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
> at
> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
> at
> org.apache.catalina.core.TestAsyncContextImpl$Bug49567Servlet$1$1.run(TestAsyncContextImpl.java:383)
> at java.base/java.lang.Thread.run(Thread.java:1583)
> 22-Feb-2024 11:19:24.685 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> 22-Feb-2024 11:19:24.693 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 22-Feb-2024 11:19:24.729 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
> 22-Feb-2024 11:19:24.739 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio-127.0.0.1-auto-11-46529"]
>
>
> or as a variation:
>
> 08-Mar-2024 14:44:59.132 INFO [main]
> org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
> [testBug49528]
> 08-Mar-2024 14:44:59.141 INFO [main]
> org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10"]
> 08-Mar-2024 14:44:59.151 INFO [main]
> org.apache.catalina.core.StandardService.startInternal Starting service
> [Tomcat]
> 08-Mar-2024 14:44:59.151 INFO [main]
> org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
> engine: [Apache Tomcat/9.0.86sp1]
> 08-Mar-2024 14:44:59.170 INFO [main]
> org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> java.lang.NullPointerException: Cannot invoke
> "org.apache.catalina.connector.Request.getCoyoteRequest()" because
> "this.request" is null
> at
> org.apache.catalina.core.AsyncContextImpl.isStarted(AsyncContextImpl.java:295)
> at
> org.apache.catalina.connector.Request.isAsyncStarted(Request.java:1715)
> at
> org.apache.catalina.connector.RequestFacade.isAsyncStarted(RequestFacade.java:749)
> at
> org.apache.catalina.core.TestAsyncContextImpl$Bug49528Servlet$1.run(TestAsyncContextImpl.java:303)
> at
> org.apache.catalina.core.AsyncContextImpl$RunnableWrapper.run(AsyncContextImpl.java:543)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
> at java.base/java.lang.Thread.run(Thread.java:1583)
> 08-Mar-2024 14:45:00.196 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> 08-Mar-2024 14:45:00.198 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 08-Mar-2024 14:45:00.217 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
> 08-Mar-2024 14:45:00.219 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio2-127.0.0.1-auto-10-37101"]
>
>
> In addition to these failures I also see NullPointerExceptions in other
> places and other test cases in TestAsyncContextImpl. Those typically go
> unnoticed, because they do not result in a test failure. It seems they
> happen during test shutdown, so they might be unrelated and not
> important. An example:
>
> 17-Jan-2024 15:14:13.604 INFO [main]
> org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
> 17-Jan-2024 15:14:13.611 INFO [main]
> org.apache.catalina.core.StandardService.stopInternal Stopping service
> [Tomcat]
> 17-Jan-2024 15:14:13.616 INFO [main]
> org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
> 17-Jan-2024 15:14:13.621 SEVERE [http-nio-127.0.0.1-auto-44-exec-1]
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun Error
> running socket processor
> java.lang.NullPointerException
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1797)
> at
> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:750)
> Exception in thread "http-nio-127.0.0.1-auto-44-exec-1"
> java.lang.NullPointerException
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.getSelectionKey(NioEndpoint.java:1835)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1813)
> at
> org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
> at
> org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
> at
> org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
> at java.lang.Thread.run(Thread.java:750)
> 17-Jan-2024 15:14:13.631 INFO [main]
> org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
> ["http-nio-127.0.0.1-auto-44-53668"]
Ok, so I don't know about the rest for now, but however for NIO, it
has a lot of important refactorings and fixes in newer Java versions.
The code causing the NPE here is the workaround to avoid a ridiculous
deadlock (is this particular case, simply closing a channel could have
the NIO internal code deadlock itself - Tomcat is not holding any lock
or anything, obviously). Maybe it could be a bit more defensive to
avoid the NPE ...
Basically Oracle "abandoned" NIO for a while after Java 1.7, they did
NIO2 instead. NIO2 seemed stable and clean (IMO it is). Then after a
while people were still using NIO and it had all sorts of problems, so
they went back and actually refactored significantly. Java 11 has
these fixes. Then later they added features that are not in NIO2 like
the Unix domain sockets. So now NIO2 is the "abandoned" one.
My conclusion is that NIO has more issues on Java 1.8 (so probably
consider NIO2 instead ?), but NIO is fine on Java 11+, and then might
be "better" on Java 17+ (because new features, always a good thing).
Rémy
>
>
> Thanks and regards,
>
> Rainer
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org