HTTP/2 test intermittent failure

[spericas]

We've seen multiple, intermittent failures of the following test in the pipeline:

io.helidon.tests.apps.bookstore.se.Http2SslTest

Test uses somewhat old okhttp client. Output is:

Error:  Tests run: 4, Failures: 3, Errors: 0, Skipped: 0, Time elapsed: 1.001 s <<< FAILURE! - in io.helidon.tests.apps.bookstore.se.Http2SslTest
Error:  io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2SslPostFirst  Time elapsed: 0.054 s  <<< FAILURE!
java.lang.AssertionError: 

Expected: is <200>
     but: was <409>
	at io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2SslPostFirst(Http2SslTest.java:77)

Error:  io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2SslCompression  Time elapsed: 0.104 s  <<< FAILURE!
java.lang.AssertionError: 

Expected: is <200>
     but: was <409>
	at io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorld(Http2SslTest.java:119)
	at io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2SslCompression(Http2SslTest.java:68)

Error:  io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2Ssl  Time elapsed: 0.111 s  <<< FAILURE!
java.lang.AssertionError: 

Expected: is <200>
     but: was <409>
	at io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorld(Http2SslTest.java:119)
	at io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2Ssl(Http2SslTest.java:63)

[INFO] 
[INFO] Results:
[INFO] 
Error:  Failures: 
Error:    Http2SslTest.testHelloWorldHttp2Ssl:63->testHelloWorld:119 
Expected: is <200>
     but: was <409>
Error:    Http2SslTest.testHelloWorldHttp2SslCompression:68->testHelloWorld:119 
Expected: is <200>
     but: was <409>
Error:    Http2SslTest.testHelloWorldHttp2SslPostFirst:77 
Expected: is <200>
     but: was <409>
Error:    SslTest.testHelloWorldSsl:64 
Expected: is <200>
     but: was <409>
[INFO] 
Error:  Tests run: 6, Failures: 4, Errors: 0, Skipped: 0

With some test tweaks (the test incorrectly uses HTTP/2 in some cases), the following output was produced:

2023.06.23 18:17:46 INFO io.helidon.nima.webserver.ServerListener Thread[#44,server-@default-listener,5,main]: [0x01eb6e1c] @default socket closed.
2023.06.23 18:17:46 INFO io.helidon.nima.webserver.LoomServer Thread[#1,main,5,main]: Níma server stopped all channels.
Error:  Tests run: 4, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 0.928 s <<< FAILURE! - in io.helidon.tests.apps.bookstore.se.Http2SslTest
Error:  io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2SslCompression  Time elapsed: 0.007 s  <<< ERROR!
java.io.IOException: TYPE_GOAWAY unexpected error code: 5

Error:  io.helidon.tests.apps.bookstore.se.Http2SslTest.testHelloWorldHttp2Ssl  Time elapsed: 0.136 s  <<< ERROR!
java.io.IOException: TYPE_GOAWAY unexpected error code: 5

[INFO] 
[INFO] Results:
[INFO] 
Error:  Errors: 
Error:    Http2SslTest.testHelloWorldHttp2Ssl » IO TYPE_GOAWAY unexpected error code: 5
Error:    Http2SslTest.testHelloWorldHttp2SslCompression » IO TYPE_GOAWAY unexpected err...
Error:    SslTest.testHelloWorldSsl » IO TYPE_GOAWAY unexpected error code: 5
[INFO] 

[danielkec]

Probability is around 1:4000

BookService returns 409 when book with same isbn already exist:

    private void addBook(Book book, ServerResponse response) {
        if (BOOK_STORE.contains(book.getIsbn())) {
            response.status(Http.Status.CONFLICT_409).send();
        } else {
            BOOK_STORE.store(book);
            response.status(Http.Status.OK_200).send();
        }
    }

All impacted tests are doing POST with okHttp client >> add book:

Sending request https://localhost:8080/books on Connection{localhost:8080, proxy=DIRECT hostAddress=localhost/127.0.0.1:8080 cipherSuite=TLS_AES_256_GCM_SHA384 protocol=h2}
Accept-Encoding: gzip
Content-Type: application/json; charset=utf-8
Content-Length: 522
Host: localhost:8080
Connection: Keep-Alive
User-Agent: okhttp/3.14.1

Being received by server:

2023.06.28 13:37:36 FINER io.helidon.nima.http2.Http2LoggingFrameListener.recv VirtualThread[#67468,[0x51952ba0 0x76ada5f9] Nima socket]/runnable@ForkJoinPool-1-worker-13: [0x51952ba0 0x76ada5f9] recv headers:
PseudoHeaders{authority='localhost:8080', method=POST, path='/books', scheme='https', status=null}
Accept-Encoding: gzip (changing)
User-Agent: okhttp/3.14.1 (changing)
Content-Length: 522
Content-Type: application/json; charset=utf-8

OkClient intermittently sends arbitrary RST_STREAM for already closed stream:

io.helidon.nima.http2.Http2Exception: Stream 3 was never created and has lower ID than last: 5
	at io.helidon.nima.http2.webserver.Http2Connection.stream(Http2Connection.java:704)
	at io.helidon.nima.http2.webserver.Http2Connection.rstStream(Http2Connection.java:673)

Order of things breaking the tests

1. okclient send POST /book
2. okclient sends arbitrary RST_STREAM -> Nima respods with GO_AWAY
3. okclient does retry but book has been already persisted, that leads correctly to 409

[danielkec]

RFC 9113 §5.1
A stream also enters the "closed" state after an endpoint either sends or receives a RST_STREAM frame.
...
An endpoint MUST NOT send frames other than PRIORITY on a closed stream.

[danielkec]

Created bug report square/okhttp#7913, we should switch to another client

[spericas]

@danielkec Could we upgrade to a more recent version?

[danielkec]

@spericas There is no version to upgrade to, square/okhttp/issues/6171 is still open