Hi there,
I get sporadic http2 test failures when running the many
JVM/connector/platform combinations against the current tags of TC 9.0,
10.1 and 11.
It happens most frequently for TC 9, but I looks like it also applies to
TC 10.1 and 11 but much more rarely.
Here's a list of the combinations, where the test run produced an error:
9.0
- org.apache.coyote.http2.TestHttp2Section_8_1 FAILED
adopt_jdk1.8.0-rhel6.x86_64-jsse
amazon_jdk1.8.0-rhel7.x86_64-jsse
oracle_jdk1.8.0-rhel9.x86_64-jsse
rh_jdk1.8.0-rhel8.x86_64-jsse
adopt_jdk11-rhel6.x86_64-jsse
oracle_jdk11-sles15.x86_64-jsse
- org.apache.coyote.http2.TestStreamProcessor FAILED
adopt_jdk1.8.0-rhel7.x86_64-jsse
amazon_jdk1.8.0-rhel6.x86_64-jsse
amazon_jdk1.8.0-sles12.x86_64-jsse
oracle_jdk1.8.0-rhel6.x86_64-jsse
zulu_jdk1.8.0-rhel6.x86_64-jsse
zulu_jdk1.8.0-rhel7.x86_64-jsse
zulu_jdk1.8.0-sles12.x86_64-jsse
adopt_jdk11-sles15.x86_64-jsse
amazon_jdk11-rhel9.x86_64-jsse
oracle_jdk11-sles12.x86_64-jsse
rh_jdk11-rhel9.x86_64-jsse
zulu_jdk11-rhel9.x86_64-jsse
10.1
- org.apache.coyote.http2.TestStreamProcessor FAILED
zulu_jdk11-sles11.x86_64-jsse
zulu_jdk11-sles15.x86_64-jsse
adopt_jdk17-sles11.x86_64-jsse
oracle_jdk21-rhel6.x86_64-jsse
11.0
- org.apache.coyote.http2.TestHttp2Section_8_1 FAILED
jdk23-rhel7.x86_64-jsse
So it seems it can happen for each of the platforms and JVM versions.
I did not check each occurrence but here are examples which all also
have a NullPointer in the access log. I don't know whether that triggers
the failure or is just another symptom triggered by the same root cause.
A) org.apache.coyote.http2.TestStreamProcessor
==============================================
- jsse_amazon_jdk1.8.0-sles12.x86_64 NIO2
Testcase: testValidateRequestURI[0: loop [0], useAsyncIO[false]] took
0.169 sec
FAILED
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
junit.framework.AssertionFailedError:
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
at
org.apache.coyote.http2.TestStreamProcessor.testValidateRequestURI(TestStreamProcessor.java:347)
...
Testcase: testValidateRequestMethod[0: loop [0], useAsyncIO[false]] took
0.221 sec
FAILED
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
junit.framework.AssertionFailedError:
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
at
org.apache.coyote.http2.TestStreamProcessor.testValidateRequestMethod(TestStreamProcessor.java:258)
and:
30-Jul-2024 19:33:57.149 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio2-127.0.0.1-auto-8-37726"]
30-Jul-2024 19:33:57.168 WARNING [http-nio2-127.0.0.1-auto-8-exec-6]
org.apache.catalina.connector.CoyoteAdapter.log Exception while
attempting to add an entry to the access log
java.lang.NullPointerException
at
org.apache.catalina.valves.AbstractAccessLogValve$ByteSentElement.addElement(AbstractAccessLogValve.java:1268)
at
org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:686)
at
org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:48)
at
org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:271)
at
org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:489)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:443)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:92)
at
org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
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.lang.Thread.run(Thread.java:750)
30-Jul-2024 19:33:57.172 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-8-37726"]
...
30-Jul-2024 19:33:57.795 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio2-127.0.0.1-auto-12-33381"]
30-Jul-2024 19:33:57.820 WARNING [http-nio2-127.0.0.1-auto-12-exec-5]
org.apache.catalina.connector.CoyoteAdapter.log Exception while
attempting to add an entry to the access log
java.lang.NullPointerException
at
org.apache.catalina.valves.AbstractAccessLogValve$ByteSentElement.addElement(AbstractAccessLogValve.java:1268)
at
org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:686)
at
org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:48)
at
org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:271)
at
org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:489)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:443)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:92)
at
org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
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.lang.Thread.run(Thread.java:750)
30-Jul-2024 19:33:57.824 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-12-33381"]
- jsse_zulu_jdk1.8.0-sles12.x86_64 NIO
Testcase: testValidateRequestURI[0: loop [0], useAsyncIO[false]] took
0.291 sec
FAILED
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
junit.framework.AssertionFailedError:
expected:<...3-Header-[:status]-[[4]00]
3-Header-[date]-...> but was:<...3-Header-[:status]-[[5]00]
3-Header-[date]-...>
at
org.apache.coyote.http2.TestStreamProcessor.testValidateRequestURI(TestStreamProcessor.java:347)
30-Jul-2024 17:12:50.468 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio-127.0.0.1-auto-8-45562"]
30-Jul-2024 17:12:50.497 WARNING [http-nio-127.0.0.1-auto-8-exec-4]
org.apache.catalina.connector.CoyoteAdapter.log Exception while
attempting to add an entry to the access log
java.lang.NullPointerException
at
org.apache.catalina.valves.AbstractAccessLogValve$ByteSentElement.addElement(AbstractAccessLogValve.java:1268)
at
org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:686)
at
org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:48)
at
org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:271)
at
org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:489)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:443)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:92)
at
org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
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.lang.Thread.run(Thread.java:750)
30-Jul-2024 17:12:50.503 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-127.0.0.1-auto-8-45562"]
Testcase: testSchemeHeaderInvalid01[0: loop [0], useAsyncIO[false]] took
0.213 sec
FAILED
3-HeadersStart
3-Header-[:status]-[500]
3-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
3-HeadersEnd
expected:<...3-Header-[:status]-[[4]00]
> but was:<...3-Header-[:status]-[[5]00]
>
junit.framework.AssertionFailedError: 3-HeadersStart
3-Header-[:status]-[500]
3-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
3-HeadersEnd
expected:<...3-Header-[:status]-[[4]00]
> but was:<...3-Header-[:status]-[[5]00]
>
at
org.apache.coyote.http2.TestHttp2Section_8_1.doInvalidPseudoHeaderTest(TestHttp2Section_8_1.java:409)
at
org.apache.coyote.http2.TestHttp2Section_8_1.testSchemeHeaderInvalid01(TestHttp2Section_8_1.java:449)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
B) org.apache.coyote.http2.TestHttp2Section_8_1
===============================================
jsse_oracle_jdk11-sles15.x86_64 NIO
31-Jul-2024 05:27:52.514 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio-127.0.0.1-auto-7-36277"]
31-Jul-2024 05:27:52.573 WARNING [http-nio-127.0.0.1-auto-7-exec-4]
org.apache.catalina.connector.CoyoteAdapter.log Exception while
attempting to add an entry to the access log
java.lang.NullPointerException
at
org.apache.catalina.valves.AbstractAccessLogValve$ByteSentElement.addElement(AbstractAccessLogValve.java:1268)
at
org.apache.catalina.valves.AbstractAccessLogValve.log(AbstractAccessLogValve.java:686)
at
org.apache.catalina.core.AccessLogAdapter.log(AccessLogAdapter.java:48)
at
org.apache.catalina.core.StandardEngine.logAccess(StandardEngine.java:271)
at
org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:489)
at
org.apache.coyote.http2.StreamProcessor.service(StreamProcessor.java:443)
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
at
org.apache.coyote.http2.StreamProcessor.process(StreamProcessor.java:92)
at
org.apache.coyote.http2.StreamRunnable.run(StreamRunnable.java:35)
at
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
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:834)
31-Jul-2024 05:27:52.581 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-127.0.0.1-auto-7-36277"]
Best regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
