Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WIP: Support HTTP2 protocol + Kinesis integration test puzzle #830

Draft
wants to merge 13 commits into
base: main
Choose a base branch
from
Draft

WIP: Support HTTP2 protocol + Kinesis integration test puzzle #830

wants to merge 13 commits into from

Conversation

jtjeferreira
Copy link
Contributor

depends on #829

This PR adds support for HTTP/2 protocol in AWS SDK HttpClient. Since the pekko-http support for http/2 is different than for http (it only support " Host-Level" and not "Request-Level" API) the implementation is a bit more tricky.

However, I found a problem when writing integration tests: the test KinesisITTest#list streams in parallel runs successfully in about 2 seconds, but if I increase number of clients from 5 to 6 it gets stuck and takes more than 60s to finish...

Can someone confirm they see this same behavior:

  • configure AWS credentials
  • run aws-spi-pekko-http/it:testOnly org.apache.pekko.stream.connectors.awsspi.kinesis.KinesisITTest -- -z "list streams"
  • it should take 2s ✅
  • change "list streams" test to use 6 clients instead of 5
  • run test again
  • test pass, but takes more than 60s ❌

@pjfanning
Copy link
Contributor

Unfortunately, I don't have an AWS account to test those Kinesis tests against.

@jtjeferreira jtjeferreira mentioned this pull request Sep 26, 2024
Draft
@jtjeferreira
Copy link
Contributor Author

By comparing the logs of list streams test with list streams in parallel, I noticed these log lines:

✅

[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [ UP ] Element:    0 SETT  SETTINGS_MAX_CONCURRENT_STREAMS -> 5, SETTINGS_INITIAL_WINDOW_SIZE -> 1048576, SETTINGS_MAX_HEADER_LIST_SIZE -> 16384
[Http2ClientDemux(pekko://aws-pekko-http)] Got 3 settings!
[Http2ClientDemux(pekko://aws-pekko-http)] Setting initial window to 1048576
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [1] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Ignoring setting SETTINGS_MAX_HEADER_LIST_SIZE -> 16384 (in Demux)
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from WaitingForData to Idle
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from Idle to WaitingForData
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [DOWN] Element:    0 SETA  SETTINGS_MAX_CONCURRENT_STREAMS -> 5, SETTINGS_INITIAL_WINDOW_SIZE -> 1048576, SETTINGS_MAX_HEADER_LIST_SIZE -> 16384
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [ UP ] Element:    0 WIND  + 1966082
[Http2ClientDemux(pekko://aws-pekko-http)] Updating outgoing connection window by 1966082 to 2031615
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [ UP ] Element:    0 SETA
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [ UP ] Element:    1 HEAD  :status -> 200, x-amzn-requestid -> x-amzn-requestid: e8b5205a-b511-6707-b7da-4d6ee15c480c, x-amz-id-2 -> x-amz-id-2: gyTW39DLO+UMAdCvml6DeWqqMpyVNDG2RVep5GMfRo+loNQAQt4SglrWalTWv5PquPMtcb54RyLQePNa1866dJ559aPW6QKw, date -> Date: Thu, 26 Sep 2024 14:08:52 GMT, content-type -> application/x-amz-cbor-1.1, content-length -> 50
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [1] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocal after handling [handleStreamEvent(ParsedHeadersFrame)]
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [ UP ] Element:    1 DATA ES bf 6e 48 61 73 4d 6f 72 65 53 74 72 65 61 6d 73 [... 34 more bytes]
[Http2ClientDemux(pekko://aws-pekko-http)] Received DATA 50 for stream [1], remaining window space now 65485, buffered: 50
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from WaitingForData to Idle
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [1] changed state: HalfClosedLocal -> HalfClosedLocal after handling [handleStreamEvent(DataFrame)]
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [DOWN] Element:    0 WIND  + 9934465
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from Idle to WaitingForData
[Http2ClientDemux(pekko://aws-pekko-http)] Dispatched chunk of 50 for stream [1], remaining window space now 65485, buffered: 0
[Http2ClientDemux(pekko://aws-pekko-http)] adjusting con-level window by 0, stream-level window by 446515, remaining window space now 65485, buffered: 0, remaining connection window space now 9999950, total buffered: 0
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [1] changed state: HalfClosedLocal -> Closed after handling [incomingStreamPulled]
[Http2ClientDemux(pekko://aws-pekko-http)] Closing connection after all streams are done and all data has been flushed.
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-0)] [DOWN] Upstream finished.

❌

[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Element:    0 SETT  SETTINGS_MAX_CONCURRENT_STREAMS -> 5, SETTINGS_INITIAL_WINDOW_SIZE -> 1048576, SETTINGS_MAX_HEADER_LIST_SIZE -> 16384
[Http2ClientDemux(pekko://aws-pekko-http)] Got 3 settings!
[Http2ClientDemux(pekko://aws-pekko-http)] Setting initial window to 1048576
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [1] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [3] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [7] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [9] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [11] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [5] changed state: HalfClosedLocalWaitingForPeerStream -> HalfClosedLocalWaitingForPeerStream after handling [distributeWindowDeltaToAllStreams]
[Http2ClientDemux(pekko://aws-pekko-http)] Ignoring setting SETTINGS_MAX_HEADER_LIST_SIZE -> 16384 (in Demux)
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from WaitingForData to Idle
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [DOWN] Element:    0 SETA  SETTINGS_MAX_CONCURRENT_STREAMS -> 5, SETTINGS_INITIAL_WINDOW_SIZE -> 1048576, SETTINGS_MAX_HEADER_LIST_SIZE -> 16384
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from Idle to WaitingForData
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Element:    0 WIND  + 1966082
[Http2ClientDemux(pekko://aws-pekko-http)] Updating outgoing connection window by 1966082 to 2031605
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Element:    0 SETA
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Element:   11 RSET  REFUSED_STREAM
[Http2ClientDemux(pekko://aws-pekko-http)] Received unexpected frame of type RstStreamFrame for stream 11 in state HalfClosedLocalWaitingForPeerStream
[Http2ClientDemux(pekko://aws-pekko-http)] Changing state from WaitingForData to Idle
[Http2ClientDemux(pekko://aws-pekko-http)] Incoming side of stream [11] changed state: HalfClosedLocalWaitingForPeerStream -> Closed after handling [handleStreamEvent(RstStreamFrame)]
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [DOWN] Element:    0 GOAY  lastStreamId = 11, errorCode = PROTOCOL_ERROR, debug = Received unexpected frame of type RstStreamFrame for stream 11 in state HalfClosedLocalWaitingForPeerStream

(streams 7, 3, 5, 1, 9 successfully receive data and are closed)

(1 minute passes)

[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Element:    0 GOAY  lastStreamId = 11, errorCode = NO_ERROR, debug =
[Http2ClientDemux(pekko://aws-pekko-http)] Got unhandled event GoAwayFrame(11,NO_ERROR,debug:<hidden>)
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [ UP ] Upstream finished.
[org.apache.pekko.stream.Log(pekko://aws-pekko-http/system/Materializers/StreamSupervisor-1)] [DOWN] Upstream finished.

Retryable error detected. Will retry in 71ms. Request attempt number 1
software.amazon.awssdk.services.kinesis.model.KinesisException: Service returned HTTP status code 502 (Service: Kinesis, Status Code: 502, Request ID: null)

1 request is retried and test eventually passes

Important bits:

  • On Got 3 settings! we received a SETTINGS_MAX_CONCURRENT_STREAMS with value 5, but 6 requests were already sent.
  • On Received unexpected frame of type RstStreamFrame for stream 11 in state HalfClosedLocalWaitingForPeerStream and above Element: 11 RSET REFUSED_STREAM.
    • The Error code is REFUSED_STREAM
    • The RFC states that when the error code is REFUSED_STREAM the request can be safely retried: The REFUSED_STREAM error code can be included in a RST_STREAM frame to indicate that the stream is being closed prior to any processing having occurred. Any request that was sent on the reset stream can be safely retried.

So I think that this is a bug in http2 support of pekko-http... cc @jrudolph @raboof ?

@pjfanning
Copy link
Contributor

Is it possible to also support HTTP 1.1? It might be a nice option to be able to use a HTTP 1.1 client if there are issues with the HTTP/2 one.

@jtjeferreira
Copy link
Contributor Author

Is it possible to also support HTTP 1.1? It might be a nice option to be able to use a HTTP 1.1 client if there are issues with the HTTP/2 one.

Yes, HTTP 1.1 is supported and the default except for the kinesis client is the only that "forces" the use of HTTP/2. However, before this PR the PekkoClient only supports HTTP/1 and kinesis works fine with it. From what I could research [1], only kinesis servers support http/2

@jtjeferreira jtjeferreira mentioned this pull request Oct 1, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@jtjeferreira @pjfanning