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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
