Jetty client is not responding to GO_AWAY packet received from (Jetty) Server and continue to send traffic on same connection

[prathamk]

Jetty version(s)
Jetty 9.x is now at End of Community Support

Java version/vendor (use: java -version)
java version "1.8.0_331"
Java(TM) SE Runtime Environment (build 1.8.0_331-b09)

OS type/version
NAME="SLES"
VERSION="15-SP2"
VERSION_ID="15.2"
PRETTY_NAME="SUSE Linux Enterprise Server 15 SP2"

Description
Do not report security issues here! See Jetty Security Reports.
Jetty client is not responding to GO_AWAY packet received from (Jetty) Server and continue to send traffic on same connection.

We have observed this behavior from Jetty version 9.4.36 onwards. Our scenario is working fine on Jetty version 9.4.32. Not tested the in between versions.

Scenario:
In our scenario, we are sending the traffic via Jetty Client toward Envoy. On restart of Envoy pod, the envoy is sending the GO_AWAY frame towards client before termination. But Jetty client is not responding to the GO_AWAY frame. During the time, Jetty client is trying to send the data frames over the same connection and requests are getting failed with "IllegalStateException : session closed".

In our scenario, the Envoy again sends the GO_AWAY frame (if doesn't receive the response for the initial GO_AWAY frame) towards client after 5 sec. At that time it replies to the GO_AWAY frame. Please see below in tcp-dump screenshot.

Whereas, the same scenario with version 9.4.32, we didn't observe this behavior, its replying to GO_AWAY frame with response immediately. Please see below in tcp-dump screenshot.

Please find the Jetty client logs for when we have reproduced the issue:

2022-10-02 08:32:01.170:DBUG:oejh.HTTP2Session:Worker-18: Created stream #69 for HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268373480,recvWindow=16772356,state=[streams=0,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
2022-10-02 08:32:01.171:DBUG:oejh.HTTP2Session:Worker-18: Created local HTTP2Stream@4f918c69#69@2e2da3a7{sendWindow=268435456,recvWindow=8388608,reset=false/false,NOT_CLOSED,age=0,attachment=null}
2022-10-02 08:32:01.171:DBUG:oejh.HTTP2Session:Worker-18: Generated DataFrame@41566beb#69{length:1654,end=true}, length/window/data=1654/268373480/1654
2022-10-02 08:32:01.171:DBUG:oejh.HTTP2Session:Worker-18: Flushed 24/1687 frame bytes for HeadersFrame@4569e719#69{end=false}
2022-10-02 08:32:01.172:DBUG:oejh.HTTP2Session:Worker-18: Flushed 1663/1663 frame bytes for DataFrame@41566beb#69{length:0,end=true}
2022-10-02 08:32:01.172:DBUG:oejh.HTTP2Session:Worker-18: Opened stream HTTP2Stream@4f918c69#69@2e2da3a7{sendWindow=268433802,recvWindow=8388608,reset=false/false,LOCALLY_CLOSING,age=1,attachment=HttpChannelOverHTTP2@42961910(exchange=HttpExchange@6b61d0{req=HttpRequest[POST /nchf-convergedcharging/v2/chargingdata HTTP/2.0]@43da5770[PENDING/null] res=HttpResponse[null 0 null]@312165d3[PENDING/null]})[send=HttpSenderOverHTTP2@76a1fdc6(req=HEADERS,snd=SENDING,failure=null),recv=HttpReceiverOverHTTP2@14677d16(rsp=IDLE,failure=null)]} for HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772356,state=[streams=1,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
**2022-10-02 08:32:01.187:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Received GoAwayFrame@c34a968{2147483647/no_error/}** on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772356,state=[streams=1,NOT_CLOSED,goAwayRecv=null,goAwaySent=null,failure=null]}
2022-10-02 08:32:01.188:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Waiting non-graceful GOAWAY for HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772356,state=[streams=1,REMOTELY_CLOSED,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:01.189:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Received DataFrame@19ade3d4#69{length:260,end=false} on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772356,state=[streams=1,**REMOTELY_CLOSED**,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:01.190:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Received DataFrame@6387e648#69{length:10,end=true} on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772096,state=[streams=1,**REMOTELY_CLOSED**,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:01.190:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Removed local HTTP2Stream@4f918c69#69@2e2da3a7{sendWindow=268433802,recvWindow=8388338,reset=false/false,CLOSED,age=19,attachment=HttpChannelOverHTTP2@42961910(exchange=HttpExchange@6b61d0{req=HttpRequest[POST /nchf-convergedcharging/v2/chargingdata HTTP/2.0]@43da5770[TERMINATED/null] res=HttpResponse[HTTP/2.0 201 null]@312165d3[PENDING/null]})[send=HttpSenderOverHTTP2@76a1fdc6(req=QUEUED,snd=COMPLETED,failure=null),recv=HttpReceiverOverHTTP2@14677d16(rsp=CONTENT,failure=null)]} from HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=1,REMOTELY_CLOSED,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:01.190:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Closed stream HTTP2Stream@4f918c69#69@2e2da3a7{sendWindow=268433802,recvWindow=8388338,reset=false/false,CLOSED,age=19,attachment=HttpChannelOverHTTP2@42961910(exchange=HttpExchange@6b61d0{req=HttpRequest[POST /nchf-convergedcharging/v2/chargingdata HTTP/2.0]@43da5770[TERMINATED/null] res=HttpResponse[HTTP/2.0 201 null]@312165d3[PENDING/null]})[send=HttpSenderOverHTTP2@76a1fdc6(req=QUEUED,snd=COMPLETED,failure=null),recv=HttpReceiverOverHTTP2@14677d16(rsp=CONTENT,failure=null)]} for HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=1,REMOTELY_CLOSED,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:01.191:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-77: Destroyed stream #69 for HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=1,REMOTELY_CLOSED,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
**2022-10-02 08:32:06.184:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Received GoAwayFrame@31cf136{69/no_error/}** on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=0,REMOTELY_CLOSED,goAwayRecv=GoAwayFrame@c34a968{2147483647/no_error/},goAwaySent=null,failure=null]}
2022-10-02 08:32:06.186:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Executing zero streams action on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
**2022-10-02 08:32:06.188:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Sending GoAwayFrame@21abae80{0/no_error/close}** on HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
2022-10-02 08:32:06.188:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Flushed 22/22 frame bytes for GoAwayFrame@21abae80{0/no_error/close}
2022-10-02 08:32:06.189:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Terminating HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
2022-10-02 08:32:06.189:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Disconnecting HTTP2ClientSession@2e2da3a7{local:/xx.xx.245.185:60116,remote:om.server.se/xx.xx.245.193:80,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
2022-10-02 08:32:06.191:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Closing no_error/ HTTP2ClientSession@2e2da3a7{local:0.0.0.0/0.0.0.0:60116,remote:null,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
2022-10-02 08:32:06.191:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Already closed, ignored GoAwayFrame@4b5414cb{0/no_error/} for HTTP2ClientSession@2e2da3a7{local:0.0.0.0/0.0.0.0:60116,remote:null,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
2022-10-02 08:32:06.191:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-75: Already closed, ignoring ISHUT for HTTP2ClientSession@2e2da3a7{local:0.0.0.0/0.0.0.0:60116,remote:null,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}
**2022-10-02 08:32:06.192:DBUG:oejh.HTTP2Session:HttpClient@7e0b85f9-79: Halting (stop) for HTTP2ClientSession@2e2da3a7**{local:0.0.0.0/0.0.0.0:60116,remote:null,sendWindow=268371826,recvWindow=16772086,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@31cf136{69/no_error/},goAwaySent=GoAwayFrame@21abae80{0/no_error/close},failure=null]}

How to reproduce?

Described above.

[joakime]

Jetty 9.x is now at End of Community Support.

• End of Community Support for Jetty 9.x - June 2022 #7958

Does this happen with Jetty 10.x?

[praveenchandna]

Our application is supported on Java 8.x , whereas Jetty 10.x requires Java 11.x so didn't tried on it.
Is it a known issue or is it Fixed on Jetty 10.x ?

Thanks !!

[sbordet]

@praveenchandna see #5310.

Jetty is now following the HTTP/2 specification more closely, so Envoy sending a "graceful" GOAWAY must not be replied yet, until Envoy sends a final GOAWAY, which Jetty's client replies to.

The behavior you see is correct.

[prathamk]

Hi @sbordet Thanks for your reply.

Checked the issue #5310, and what we observe is similar, but the issue in our scenario is on top of that.

As you said, the following is the order:

1. Envoy is sending graceful GO_AWAY with Last-Stream-ID set as Integer MAX.
2. Jetty client is setting the state as REMOTELY_CLOSED, and waiting for non-graceful GO_AWAY.
3. After sometime, envoy is again sending GO_AWAY, this time with Last-Stream-ID set as 69 (As in logs above).
4. This time Jetty sets the state as CLOSING, and sends back the GO_AWAY frame.

This is as per the HTTP/2 specification also:
A server that is attempting to gracefully shut down a connection SHOULD send an initial GOAWAY frame with the last stream identifier set to 2^31-1 and a NO_ERROR code. This signals to the client that a shutdown is imminent and that initiating further requests is prohibited. After allowing time for any in-flight stream creation (at least one round-trip time), the server can send another GOAWAY frame with an updated last stream identifier. This ensures that a connection can be cleanly shut down without losing requests.

Here as per the specification, Jetty client is not sending the requests to Envoy post receiving the graceful GO_AWAY frame.

Now the issue:
Jetty client is failing the requests with exception "IllegalStateException : session closed". As it is able to acquire the connection to send request, with state marked as REMOTELY_CLOSED. These connections are only removed after the final GO_AWAY frame.

As per the specification:
This signals to the client that a shutdown is imminent and that initiating further requests is prohibited.

But Jetty client is trying to send the request on that connection (marked as REMOTELY_CLOSED). Isn't the connection with state marked as REMOTELY_CLOSED, only be used to receive response of streams sent before the graceful GO_AWAY frame, and new connection should be created at the time a new request is received?

[sbordet]

@prathamk I see your point, we will look into it.

[praveenchandna]

Hello @sbordet ,

Thanks for your reply.
Will the FIX for this issue be provided on 9.4.x ?
Not sure, but still we have looked into the code of HTTP2Session class on jetty 10.x/11.x as well but we didn't find any differences, so this issue will be there as well.

Thanks !!

[jmcc0nn3ll]

@praveenchandna There is a chance that it may be addressed in 9.4.x, but it is unlikely as that release branch is no longer actively maintained for community issues.

[sbordet]

@praveenchandna unfortunately I don't think this problem is solvable as it is inherently racy.

The client may acquire a connection which is still open, but before it actually gets the chance to send a request, the server will send the graceful GOAWAY and possibly also the normal GOAWAY.
By the time the request thread resumes, it will find that the session is now closed and it can only fail.

This is a generic problem also in HTTP/1.1 where the server could close the connection exactly when the client is about to send the request.

The only thing that we can do is to try to reduce the window of this race happening, but I'm not sure it's worth it.
The idea would be that upon receiving the first GOAWAY, the client removes the connection from the pool, so requests that are sent later will be forced to open a new connection.
However, there will still be the chance that the connection has already been acquired and that the request will fail.

Alternatively, if you know that the server is closing the connection either after a number of requests or after a fixed time, you can configure the client pool to close the connection before the server does.

[shamsimam]

Alternatively, if you know that the server is closing the connection either after a number of requests or after a fixed time, you can configure the client pool to close the connection before the server does.

Can you share configuration snippets to achieve this?

[sbordet]

HttpClientTransport transport = new HttpClientTransportOverHTTP2(http2Client);
transport.setConnectionPoolFactory(destination -> {
  HttpClient httpClient = destination.getHttpClient();
  MultiplexConnectionPool pool = new MultiplexConnectionPool(destination, httpClient.getMaxConnectionsPerDestination(), destination, httpClient.getMaxRequestsQueuedPerDestination());

  // A connection won't be used after 100 request/response cycles.
  pool.setMaxUsageCount(100);

  // Alternatively.
  // A connection won't be used after 2 minutes of usage.
  pool.setMaxDuration(120000);
});

Remember that in order to use any of these 2 mechanisms effectively, you have to somehow know that the server won't close before (or that it would be a very rare case that the server closes before).

Even if you're using the mechanisms above, I would still configure the client with a smaller idle timeout than the server.

[prathamk]

Hi @sbordet Thanks for your reply.

The only thing that we can do is to try to reduce the window of this race happening, but I'm not sure it's worth it.
The idea would be that upon receiving the first GOAWAY, the client removes the connection from the pool, so requests that are sent later will be forced to open a new connection.
However, there will still be the chance that the connection has already been acquired and that the request will fail.

Yes, to proceed around this issue, we have implemented the same behavior as you have mentioned in Jetty code. The inherent race condition is still there, but failures have been drastically reduced. Previously where we had failures somewhere around 35000, now there are failures somewhere around 10.

So there is some benefit to it, if not 100%.

Alternatively, if you know that the server is closing the connection either after a number of requests or after a fixed time, you can configure the client pool to close the connection before the server does.

Unfortunately, in our scenario, this is not known.

[sbordet]

@prathamk do you want to submit a pull request with your changes?

[sbordet]

@prathamk can you please try out #8891 and see if it works for you?

[prathamk]

@sbordet Would not be able to try the fix in Jetty 10.x as currently we are on Java 8.x. Is there any plan to down merge it in Jetty 9.x?

Thanks for the support.

[gregw]

Jetty 9.x is now at End of Community Support.

Announcement for End of Community Support for Jetty 9.x #7958

[sbordet]

@prathamk this particular change has been backported to Jetty 9.4.x because the work has been sponsored by a Webtide customer that had a similar issue.

However, consider moving away from Jetty 9.4.x and Java 8. Webtide can help you with the migration.

[prathamk]

Yeah, backlog for 2023 :)

Thanks @sbordet for the update and support.