Client sending RST_STREAM led to exceeding maxEventsPerSecond(128) threshold

[iamsanjay]

Jetty Version 10.0.20

Java Version 11

Question

In Apache Solr, IndexFetcher is an utility used to download index files. First the client would request the file list, which could be any number. After which a HTTP client is used to download all the files in the loop. Currently, Apache HTTP is being used and the plan is to migrate to Jetty HTTP2.

In local environment, below exception observed in the logs after switching to Jetty Http2.

19899 DEBUG (qtp1225317224-19) [n: c: s: r: x: t:] o.e.j.h.HTTP2Connection Processing session failure on HTTP2ServerSession@21b8f2d3{local:/127.0.0.1:50617,remote:/127.0.0.1:50623,sendWindow=16658867,recvWindow=1048576,state=[streams=0,CLOSING,goAwayRecv=null,goAwaySent=GoAwayFrame@43709453{931/enhance_your_calm_error/invalid_rst_stream_frame_rate},failure=java.io.IOException: enhance_your_calm_error/invalid_rst_stream_frame_rate]}
>   2>           => java.io.IOException: enhance_your_calm_error/invalid_rst_stream_frame_rate
>   2> 	at org.eclipse.jetty.http2.HTTP2Session.toFailure(HTTP2Session.java:633)
>   2> java.io.IOException: enhance_your_calm_error/invalid_rst_stream_frame_rate
>   2> 	at org.eclipse.jetty.http2.HTTP2Session.toFailure(HTTP2Session.java:633) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Session$StreamsState.onSessionFailure(HTTP2Session.java:2006) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Session.onSessionFailure(HTTP2Session.java:578) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Session.onConnectionFailure(HTTP2Session.java:573) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Connection.onConnectionFailure(HTTP2Connection.java:303) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.BodyParser.notifyConnectionFailure(BodyParser.java:218) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.BodyParser.connectionFailure(BodyParser.java:210) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:92) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:61) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:240) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:167) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:126) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:350) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:455) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:248) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:193) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:208) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:155) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:450) [http2-common-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) [jetty-io-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) [jetty-io-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.Invocable.invokeNonBlocking(Invocable.java:151) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.invokeAsNonBlocking(AdaptiveExecutionStrategy.java:438) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:380) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:277) [jetty-util-10.0.20.jar:10.0.20]
>   2> 	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:193) [jetty-util-10.0.20.jar:10.0.20]

Each subsequent download of file led to client sending RST_STREAM, and after some time, IMO it hits the ceiling of maxEventsPerSecond(128).

23276 DEBUG (explicit-fetchindex-cmd) [n: c: s: r: x: t:] o.a.s.h.IndexFetcher Downloading file=_d_Lucene99_0.doc size=77 checksum=2050144584 alwaysDownload=true
> 23277 DEBUG (qtp1225317224-19) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [HEADERS|129|5|295] frame header from java.nio.DirectByteBuffer[pos=9 lim=138 cap=32768]@34df2942
> 23277 DEBUG (qtp1225317224-19) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed HEADERS frame body from java.nio.DirectByteBuffer[pos=138 lim=138 cap=32768]@1
> 23278 INFO  (qtp1225317224-24-null-430) [n: c: s: r: x:collection1 t:null-430] o.a.s.c.S.Request webapp=/solr path=/replication params={generation=27&qt=/replication&file=_d_Lucene99_0.doc&checksum=true&wt=filestream&version=2.2&command=filecontent} status=0 QTime=0
> 23286 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [HEADERS|47|4|295] frame header from java.nio.DirectByteBuffer[pos=9 lim=154 cap=16384]@aaa0db56
> 23286 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed HEADERS frame body from java.nio.DirectByteBuffer[pos=56 lim=154 cap=16384]@1514d58f
> 23286 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [DATA|89|0|295] frame header from java.nio.DirectByteBuffer[pos=65 lim=154 cap=16384]@cfc03090
> 23286 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed DATA frame body from java.nio.DirectByteBuffer[pos=154 lim=154 cap=16384]@1
> 23287 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [DATA|4|0|295] frame header from java.nio.DirectByteBuffer[pos=9 lim=22 cap=16384]@d3c9dba6
> 23287 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed DATA frame body from java.nio.DirectByteBuffer[pos=13 lim=22 cap=16384]@f2a59ea6
> 23287 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [DATA|0|1|295] frame header from java.nio.DirectByteBuffer[pos=22 lim=22 cap=16384]@1
> 23287 DEBUG (h2sc-26-thread-2) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed DATA frame body from java.nio.DirectByteBuffer[pos=22 lim=22 cap=16384]@1
> 23287 DEBUG (explicit-fetchindex-cmd) [n: c: s: r: x: t:] o.a.s.h.IndexFetcher Fetched and wrote 77 bytes of file: _d_Lucene99_0.doc
> Closing input Stream
> 23287 DEBUG (qtp1225317224-19) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed [RST_STREAM|4|0|295] frame header from java.nio.DirectByteBuffer[pos=9 lim=13 cap=32768]@11ba79
> 23287 DEBUG (qtp1225317224-19) [n: c: s: r: x: t:] o.e.j.h.p.Parser Parsed RST_STREAM frame body from java.nio.DirectByteBuffer[pos=13 lim=13 cap=32768]@1
> 23290 DEBUG (explicit-fetchindex-cmd) [n: c: s: r: x: t:] o.a.s.h.IndexFetcher Downloading file=_d_Lucene99_0.tim size=238 checksum=531240994 alwaysDownload=true

In essence, I'm asking whether this behavior aligns with normal client-side stream closure practices or indicates a potential problem. Any insights or explanations regarding this matter would be greatly appreciated.

[sbordet]

It is not normal.

The client by default does not have any rate control limit: it must be explicitly configured, and I assume it is not.

Could it be that the client application cancels every stream it creates, and the server is flooded with resets, and eventually exceeds the max events per second?

Is there a way we can reproduce the issue and take a closer look?

Can you enable client-side DEBUG logs to understand why the client resets the streams?

[iamsanjay]

jetty.txt

Could it be that the client application cancels every stream it creates, and the server is flooded with resets, and eventually exceeds the max events per second?

Yes client is the one flooding server with RST_STREAM. Further investigation took me to the below code where the limit is checked.

https://github.com/jetty/jetty.project/blob/89c41b2550ed367a25d1664da8843f5a4e1019da/jetty-core/jetty-http2/jetty-http2-common/src/main/java/org/eclipse/jetty/http2/parser/ResetBodyParser.java#L88-L92

[iamsanjay]

Upon your suggestion, I enabled the logs at "org.eclipse.jetty" and got to know that there is a possibility, I am still debugging, that we may have been closing the InputStream bit early before we receive all the DataFrame and that is what, I guess, leading to send RST_FRAME. Below is the snippet of code where we are reading the InputStream.

https://github.com/apache/solr/blob/62cf3aaef34ba8f0437dbc355457e367488c8a99/solr/core/src/java/org/apache/solr/handler/IndexFetcher.java#L1831-L1850

[sbordet]

@iamsanjay from the logs I came to the same conclusion, that you are not reading the whole content.

I can see from the logs that 250 bytes are received and consumed, but the next 4 bytes are not read, and are discarded because the input stream is being closed.

It is really important that you read until the InputStream reads -1.

This means that if you are parsing JSON, and the 250 bytes would represent a full JSON document (so from the point of view of the application you have all the relevant data), you still have 4 bytes to read and you still have to read the -1 (end-of-file).

Closing the InputStream earlier would lead to a reset being sent to the server.