Hi there,
for a long time I get sporadic failures in
org.apache.coyote.http2.TestRfc9218. It happens for all branches of TC,
for NIO and NIO2 and with JSSE and tcnative. Tested platforms Linux and
Solaris see this. And JVM versions 1.8.0, 11, 17 and 21 show it. It is
also not restricted to a specific JDK vendor.
It does not happen frequently. For instance I tried running only this
test in a loop and in 225 test runs for NIO+NIO2, so 450 overall test
executions, I got 4 failing executions.
The typical failure is like this:
Testcase: testPriority[1: loop [0], useAsyncIO[true]] took 0.309 sec
FAILED
expected:<1[7]-Body-1024
> but was:<1[9]-Body-1024
>
junit.framework.AssertionFailedError: expected:<1[7]-Body-1024
> but was:<1[9]-Body-1024
>
at
org.apache.coyote.http2.TestRfc9218.testPriority(TestRfc9218.java:80)
but there are also other variations (even more rare) like
Testcase: testPriority[1: loop [0], useAsyncIO[true]] took 0.305 sec
FAILED
null
junit.framework.AssertionFailedError
at
org.apache.coyote.http2.TestRfc9218.testPriority(TestRfc9218.java:170)
Is there something I can do to provide more information, add more
logging or so? Full current log output see below.
Thanks and regards,
Rainer
Testsuite: org.apache.coyote.http2.TestRfc9218
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.061 sec
------------- Standard Output ---------------
3-HeadersStart
3-Header-[:status]-[200]
3-Header-[content-type]-[application/octet-stream]
3-Header-[content-length]-[8192]
3-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
3-HeadersEnd
3-Body-8192
3-EndOfStream
5-HeadersStart
5-Header-[:status]-[200]
5-Header-[content-type]-[application/octet-stream]
5-Header-[content-length]-[8192]
5-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
5-HeadersEnd
5-Body-8192
5-EndOfStream
7-HeadersStart
7-Header-[:status]-[200]
7-Header-[content-type]-[application/octet-stream]
7-Header-[content-length]-[8192]
7-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
7-HeadersEnd
7-Body-8192
7-EndOfStream
9-HeadersStart
9-Header-[:status]-[200]
9-Header-[content-type]-[application/octet-stream]
9-Header-[content-length]-[8192]
9-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
9-HeadersEnd
9-Body-8192
9-EndOfStream
11-HeadersStart
11-Header-[:status]-[200]
11-Header-[content-type]-[application/octet-stream]
11-Header-[content-length]-[8192]
11-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
11-HeadersEnd
11-Body-8192
11-EndOfStream
13-HeadersStart
13-Header-[:status]-[200]
13-Header-[content-type]-[application/octet-stream]
13-Header-[content-length]-[8192]
13-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
13-HeadersEnd
13-Body-8192
13-EndOfStream
15-HeadersStart
15-Header-[:status]-[200]
15-Header-[content-type]-[application/octet-stream]
15-Header-[content-length]-[8192]
15-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
15-HeadersEnd
15-Body-8192
15-EndOfStream
17-HeadersStart
17-Header-[:status]-[200]
17-Header-[content-type]-[application/octet-stream]
17-Header-[content-length]-[8192]
17-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
17-HeadersEnd
17-Body-1024
19-HeadersStart
19-Header-[:status]-[200]
19-Header-[content-type]-[application/octet-stream]
19-Header-[content-length]-[8192]
19-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
19-HeadersEnd
21-HeadersStart
21-Header-[:status]-[200]
21-Header-[content-type]-[application/octet-stream]
21-Header-[content-length]-[8192]
21-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
21-HeadersEnd
21-Body-1365
17-Body-5266
17-EndOfStream
19-Body-1560
3-HeadersStart
3-Header-[:status]-[200]
3-Header-[content-type]-[application/octet-stream]
3-Header-[content-length]-[8192]
3-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
3-HeadersEnd
3-Body-8192
3-EndOfStream
5-HeadersStart
5-Header-[:status]-[200]
5-Header-[content-type]-[application/octet-stream]
5-Header-[content-length]-[8192]
5-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
5-HeadersEnd
5-Body-8192
5-EndOfStream
7-HeadersStart
7-Header-[:status]-[200]
7-Header-[content-type]-[application/octet-stream]
7-Header-[content-length]-[8192]
7-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
7-HeadersEnd
7-Body-8192
7-EndOfStream
9-HeadersStart
9-Header-[:status]-[200]
9-Header-[content-type]-[application/octet-stream]
9-Header-[content-length]-[8192]
9-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
9-HeadersEnd
9-Body-8192
9-EndOfStream
11-HeadersStart
11-Header-[:status]-[200]
11-Header-[content-type]-[application/octet-stream]
11-Header-[content-length]-[8192]
11-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
11-HeadersEnd
11-Body-8192
11-EndOfStream
13-HeadersStart
13-Header-[:status]-[200]
13-Header-[content-type]-[application/octet-stream]
13-Header-[content-length]-[8192]
13-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
13-HeadersEnd
13-Body-8192
13-EndOfStream
15-HeadersStart
15-Header-[:status]-[200]
15-Header-[content-type]-[application/octet-stream]
15-Header-[content-length]-[8192]
15-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
15-HeadersEnd
15-Body-8192
15-EndOfStream
17-HeadersStart
17-Header-[:status]-[200]
17-Header-[content-type]-[application/octet-stream]
17-Header-[content-length]-[8192]
17-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
17-HeadersEnd
17-Body-1024
19-HeadersStart
19-Header-[:status]-[200]
19-Header-[content-type]-[application/octet-stream]
19-Header-[content-length]-[8192]
19-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
19-HeadersEnd
21-HeadersStart
21-Header-[:status]-[200]
21-Header-[content-type]-[application/octet-stream]
21-Header-[content-length]-[8192]
21-Header-[date]-[Wed, 11 Nov 2015 19:18:42 GMT]
21-HeadersEnd
------------- ---------------- ---------------
------------- Standard Error -----------------
02-Mar-2024 10:37:29.572 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testPriority[0: loop [0], useAsyncIO[false]]]
02-Mar-2024 10:37:30.822 INFO [main]
org.apache.coyote.http11.AbstractHttp11Protocol.configureUpgradeProtocol
The ["http-nio2-127.0.0.1-auto-1"] connector has been configured to
support HTTP upgrade to [h2c]
02-Mar-2024 10:37:30.823 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["http-nio2-127.0.0.1-auto-1"]
02-Mar-2024 10:37:31.013 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
02-Mar-2024 10:37:31.013 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
engine: [Apache Tomcat/9.0.86]
02-Mar-2024 10:37:31.397 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio2-127.0.0.1-auto-1-44509"]
02-Mar-2024 10:37:32.054 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-1-44509"]
02-Mar-2024 10:37:32.059 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
02-Mar-2024 10:37:32.124 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio2-127.0.0.1-auto-1-44509"]
02-Mar-2024 10:37:32.144 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["http-nio2-127.0.0.1-auto-1-44509"]
02-Mar-2024 10:37:32.188 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testPriority[1: loop [0], useAsyncIO[true]]]
02-Mar-2024 10:37:32.199 INFO [main]
org.apache.coyote.http11.AbstractHttp11Protocol.configureUpgradeProtocol
The ["http-nio2-127.0.0.1-auto-2"] connector has been configured to
support HTTP upgrade to [h2c]
02-Mar-2024 10:37:32.199 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["http-nio2-127.0.0.1-auto-2"]
02-Mar-2024 10:37:32.233 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
02-Mar-2024 10:37:32.234 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
engine: [Apache Tomcat/9.0.86]
02-Mar-2024 10:37:32.272 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio2-127.0.0.1-auto-2-45233"]
02-Mar-2024 10:37:32.442 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio2-127.0.0.1-auto-2-45233"]
02-Mar-2024 10:37:32.446 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
02-Mar-2024 10:37:32.461 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio2-127.0.0.1-auto-2-45233"]
02-Mar-2024 10:37:32.471 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["http-nio2-127.0.0.1-auto-2-45233"]
------------- ---------------- ---------------
Testcase: testPriority[0: loop [0], useAsyncIO[false]] took 2.7 sec
Testcase: testPriority[1: loop [0], useAsyncIO[true]] took 0.309 sec
FAILED
expected:<1[7]-Body-1024
> but was:<1[9]-Body-1024
>
junit.framework.AssertionFailedError: expected:<1[7]-Body-1024
> but was:<1[9]-Body-1024
>
at org.apache.coyote.http2.TestRfc9218.testPriority(TestRfc9218.java:80)
access log:
127.0.0.1 - - [02/Mar/2024:10:37:26 +0100] "GET /simple HTTP/1.1" 101 -
null 0
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-2 72
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-4 5
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-6 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-7 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-10 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-1 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-3 2
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-5 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-1-exec-8 149
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/1.1" 101 -
null 0
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-2 23
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-4 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-7 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-9 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-8 2
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-2 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-4 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-7 3
127.0.0.1 - - [02/Mar/2024:10:37:27 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio-127.0.0.1-auto-2-exec-10 148
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/1.1" 101 -
null 0
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-2 118
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-7 13
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-6 4
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-8 3
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-1 3
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-2 3
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-5 8
127.0.0.1 - - [02/Mar/2024:10:37:31 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-6 3
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-1-exec-10 194
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/1.1" 101 -
null 0
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-3 41
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-8 4
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-10 4
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-2 3
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-6 5
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-7 3
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-9 5
127.0.0.1 - - [02/Mar/2024:10:37:32 +0100] "GET /simple HTTP/2.0" 200
8192 http-nio2-127.0.0.1-auto-2-exec-10 4
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
