Incomplete uploads with HTTP/2 client & server #4948

mklinger · 2020-06-08T07:50:44Z

Jetty version
9.4.29.v20200521

Java version
OpenJDK 11.0.7

OS type/version
Ubuntu 18.04.4

Description

After upgrading to 9.4.29 in a project using HTTP/2 Jetty client and server I experienced problems with request bodies around 30k - 40k of size. It seems that the last chunk (last h2 frame?) is not transferred to the server sometimes.

In my case, this results in invalid JSON received on the server side. The size of the body read from the servlet input stream is smaller than the value given in the Content-Length request header. I made sure that my code around the client invocation produces correct JSON with the correct size. I'm using a byte-array for my JSON payload, so I can rule out I/O problems.

I had a hard time nailing down the source of the problem as I can only reproduce it in a quite big integration test of my application. This test runs 3 application processes that all communicate with each other concurrently and asynchronous. Within the test, a few hundred requests are made and usually one of them fails.

I tried to create a smaller test-case but could not reproduce the problem there. I am even unsure whether the problem is caused on the client or server side, as all traffic is encrypted and the debug log is not very clear about the number of bytes sent over the wire.

Downgrading Jetty client and server to 9.4.28 made the problem disappear.

After having a look at the HTTP/2 related changes between 9.4.28 and 9.4.29 I tried to set the recycleHttpChannels flags to false, on both, server and client side, without any effect (my tests where still failing).

May this be related to #4855 (comment) ?

I would like to kindly ask you to review the HTTP/2 related changes between 9.4.28 and 9.4.29. If I can provide any further information please let me know.

Thank you.

The text was updated successfully, but these errors were encountered:

sbordet · 2020-06-08T08:28:51Z

@mklinger it's unlikely that your problems are due to #4855, since those failure happens only when the client is sending to the server nasty failures to verify the behavior against the HTTP/2 specification.
Legit clients don't send those nasty failures and so you should not be affected by #4855.

The two major changes between .28 and .29 are stream creation and channel recycling.
Given you seem to have a problem with the last chunk, stream creation should not be an issue.
And you tested channel recycling to have no effect.

Do you have an intermediary between client and server?
Are you using Content-Encoding: gzip?

Can you please give us a server dump (see https://www.eclipse.org/jetty/documentation/current/jetty-dump-tool.html) on both client and server when this happens?

Any chance that you can run the test with DEBUG logs enabled?

mklinger · 2020-06-08T11:51:32Z

@sbordet thank you for the quick response!

Do you have an intermediary between client and server?

Client and server are communicating directly without any (Reverse-)Proxy or similar. TLS termination happens within Jetty using Conscrypt 2.4.0. My integration tests run in local Docker containers using a Docker network.

Are you using Content-Encoding: gzip?

Gzip is enabled for server responses, but currently not for client requests. The problem only appears for requests, not responses.

Can you please give us a server dump (see https://www.eclipse.org/jetty/documentation/current/jetty-dump-tool.html) on both client and server when this happens?

I will do that, but it will take some time for me to trigger the dump programmatically at the right moment.

Any chance that you can run the test with DEBUG logs enabled?

Yes, I already did that. I will try to filter the log for the problematic request/response cycle (as otherwise the log gets huge) and attach it to this ticket.

joakime · 2020-06-08T12:09:17Z

Are you using Content-Encoding: gzip?

Gzip is enabled for server responses, but currently not for client requests. The problem only appears for requests, not responses.

If you enabled this via the Jetty GzipHandler on the server side then both client request automatic gzip uncompress and server response gzip automatic compress are enabled.

When you said "but currently not for client requests" did you mean that you didn't configure Jetty Client for compressing its requests?

mklinger · 2020-06-08T13:50:52Z

@joakime I was wrong. Gzip compression is not enabled on both sides. I never see any Content-Encoding headers. However, I can see Accept-Encoding: gzip request headers from the client side. Does this make sense?

mklinger · 2020-06-08T14:11:29Z

I ran the tests with DEBUG logs enabled and here are the condensed log lines for server and client for the request that fails:

client.log
server.log

The request body should have 47682 bytes, but only 16375 bytes end up in the JSON parser.

If this doesn't help, I can also provide the full log file (which is > 100 MB)

sbordet · 2020-06-08T15:00:12Z

@mklinger seems a buffer corruption at TLS level: we pass 4 buffers with 9, 16384, 9 16384 bytes each.
SslConnection consumes 16384 on a first wrap, then 18 on a second wrap, then it thinks it's done, so something has cleared the 4th buffer.

Can you try without Conscrypt? I would like to verify whether it's a Conscrypt bug.

mklinger · 2020-06-08T15:32:32Z

@sbordet Wow, thanks for the information. My first try getting it running without Conscrypt did not succeed. I will try again tomorrow morning and come back to you. Thanks!

sbordet · 2020-06-08T15:53:39Z

@mklinger also are you serving mixed HTTP/1.1 and HTTP/2 requests?
I ask because we recently fixed #4828, which can poison the global ByteBufferPool and affect HTTP/2 as well.

Are you able to try the latest code in the `jetty-9.4.x' branch? We can help you build Jetty from that branch if you need help.

mklinger · 2020-06-10T14:23:23Z

@sbordet Unfortunately, using a build from the jetty-9.4.x branch didn't help.

sbordet · 2020-06-10T15:01:46Z

@mklinger:

did you try without Conscrypt?
do you have mixed HTTP/1.1 and HTTP/2 requests?
would you be able to change the client code and use LeakTrackingByteBufferPool?

mklinger · 2020-06-11T22:39:10Z

@sbordet

did you try without Conscrypt?

I tried. The application is a Spring Boot application and I had to find out that current Spring Boot versions force the usage of Conscrypt for Jetty HTTP/2 setup. I browsed the code but did not find a way to change that in a reasonable time.

do you have mixed HTTP/1.1 and HTTP/2 requests?

The application instances under test only do HTTP/2 requests. When double-checking, I found that the test itself uses two Jetty clients, one doing HTTP/2 and another doing HTTP/1.1. These clients are used for requests against the application instances. The test code runs in another process. The actual test failure happens for requests between application instances.

would you be able to change the client code and use LeakTrackingByteBufferPool?

I did that and got the following output when the test environment is shut down. It looks to me like this output is produced by the test process. Application instances don't produce such output. (I did that using the 9.4.29 version)

[] WARN org.eclipse.jetty.io.LeakTrackingByteBufferPool - ByteBuffer java.nio.DirectByteBuffer[pos=0 lim=0 cap=18432] leaked at:
java.lang.Throwable
	at org.eclipse.jetty.util.LeakDetector$LeakInfo.<init>(LeakDetector.java:174)
	at org.eclipse.jetty.util.LeakDetector$LeakInfo.<init>(LeakDetector.java:163)
	at org.eclipse.jetty.util.LeakDetector.acquired(LeakDetector.java:79)
	at org.eclipse.jetty.io.LeakTrackingByteBufferPool.acquire(LeakTrackingByteBufferPool.java:67)
	at org.eclipse.jetty.io.ssl.SslConnection.acquireEncryptedInput(SslConnection.java:337)
	at org.eclipse.jetty.io.ssl.SslConnection.access$800(SslConnection.java:80)
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:662)
	at org.eclipse.jetty.http2.HTTP2Connection.fill(HTTP2Connection.java:134)
	at org.eclipse.jetty.http2.HTTP2Connection.access$500(HTTP2Connection.java:44)
	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:266)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:170)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:125)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:348)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
	at java.base/java.lang.Thread.run(Thread.java:834)

sbordet · 2020-06-29T14:51:07Z

@mklinger we have done further work on the buffer corruption issue in #4967.
Can you please try the changes in branch jetty-9.4.x-4967-buffer_corruption_for_http2_failures?

mklinger · 2020-06-30T12:30:25Z

@sbordet: Unfortunately, the problem still persists using a SNAPSHOT build from branch jetty-9.4.x-4967-buffer_corruption_for_http2_failures.

sbordet · 2020-06-30T12:52:11Z

@mklinger can you please attach the DEBUG logs for the run with branch jetty-9.4.x-4967-buffer_corruption_for_http2_failures?

Also, did you try without Conscrypt?

mklinger · 2020-07-01T14:18:33Z

@sbordet here is the debug log. I tried to filter the log for the interesting parts. I hope, I got it right.

client.log
server.log

mklinger · 2020-07-01T14:44:28Z

@sbordet:

Also, did you try without Conscrypt?

I wasn't able to use something else than Conscrypt on the server side, but I managed to use the SunJSSE provider on the client side. The result was the same, the test failed with the same error.

I will dig into Spring Boot's Jetty setup code again to find a way to get the server running without Conscrypt, but I'm not very optimistic about that.

joakime · 2020-07-01T16:16:14Z

I added an issue at spring-boot as a result of the discussion on this issue.

spring-projects/spring-boot#22188

sbordet · 2020-07-02T09:09:26Z

@mklinger the client logs look ok, writing to the server 69078 bytes of PUT content.

On the server, we see a first read of 16375 bytes that is added to the HttpInput:

[qetcher-127.0.0.1:40001] 2020-07-01 13:51:03.140 DEBUG 1 --- [tp285074186-370] org.eclipse.jetty.server.HttpInput       : HttpInput@42e61dc4[c=0,q=1,[0]=Content@153d6fdc{HeapByteBuffer@436364c[p=0,l=16375,c=16375,r=16375]={<<<{"version":257,"clusterLi...10-8c2b-be1bb6db4bd4",">>>}},s=STREAM] addContent Content@153d6fdc{HeapByteBuffer@436364c[p=0,l=16375,c=16375,r=16375]={<<<{"version":257,"clusterLi...10-8c2b-be1bb6db4bd4",">>>}}

The HttpInput is in state s=STREAM.

Then the application is called, it goes through a number of filters and then lands on Spring's DispatcherServlet where the application reads the request content.
However, the first attempt to read (1 byte, probably via int ServletInputStream.read()) already shows the HttpInput in state s=EOF.

This is incorrect but we cannot find any trace in your logs of when the state was moved to EOF and it should be there.
Did you filter out lines that could show that?

Also, client and server times are a little off (the server seems to be few ms behind) - can you please confirm that?

The good news is that we don't see anymore the buffer corruption that we were seeing before - these last logs seem to show a different problem.

Can you please check what application code is doing the read of just 1 byte? Is it some filter or it's your application?

I'm baffled!

sbordet · 2021-05-05T09:13:21Z

@mklinger what's the status on this? I guess we can close it?

DenisDudinski · 2021-11-23T14:28:39Z

Hi @mklinger, @sbordet! It seems, that we experience somewhat similar problem with jetty embedded in hadoop hdfs namenode (jetty version 9.4.20.v20190813 as reported by maven). Upload silently fails on server side during upload of file, and debug log shows, that last filled ByteBuffer somehow is not applied to HttpInput, but no errors or warns is produced. Clients behaves itself in two ways - it either tells that all is ok, but file is effectively not uploaded, or shows error like 'Unexpected end of file from server'. But only sometimes, and it is impossible to predict when. I've attached two logs - one with debug info for successful upload and another one (unfortunately only as jpg image) that shows completion of failed upload. Hope it helps.
Comment to failure screen - expected uploaded size was 42772337. At EOF c=42764763. HeapByteBuffer with 7574 bytes is present but is not consumed.

snippet-fsimage-upload-success.txt

sbordet · 2021-11-27T10:30:36Z

@DenisDudinski the image you attached shows that HTTP/1.1 is in use. This issue is about HTTP/2, so please open a new issue.

github-actions · 2022-11-28T00:00:22Z

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

janbartel assigned sbordet Jul 20, 2020

github-actions bot added the Stale For auto-closed stale issues and pull requests label Nov 28, 2022

sbordet closed this as completed Nov 28, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Incomplete uploads with HTTP/2 client & server #4948

Incomplete uploads with HTTP/2 client & server #4948

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 8, 2020

joakime commented Jun 8, 2020

mklinger commented Jun 8, 2020

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 10, 2020

sbordet commented Jun 10, 2020

mklinger commented Jun 11, 2020

sbordet commented Jun 29, 2020

mklinger commented Jun 30, 2020

sbordet commented Jun 30, 2020

mklinger commented Jul 1, 2020

mklinger commented Jul 1, 2020

joakime commented Jul 1, 2020 •

edited

sbordet commented Jul 2, 2020

sbordet commented May 5, 2021

DenisDudinski commented Nov 23, 2021 •

edited

sbordet commented Nov 27, 2021

github-actions bot commented Nov 28, 2022

Incomplete uploads with HTTP/2 client & server #4948

Incomplete uploads with HTTP/2 client & server #4948

Comments

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 8, 2020

joakime commented Jun 8, 2020

mklinger commented Jun 8, 2020

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 8, 2020

sbordet commented Jun 8, 2020

mklinger commented Jun 10, 2020

sbordet commented Jun 10, 2020

mklinger commented Jun 11, 2020

sbordet commented Jun 29, 2020

mklinger commented Jun 30, 2020

sbordet commented Jun 30, 2020

mklinger commented Jul 1, 2020

mklinger commented Jul 1, 2020

joakime commented Jul 1, 2020 • edited

sbordet commented Jul 2, 2020

sbordet commented May 5, 2021

DenisDudinski commented Nov 23, 2021 • edited

sbordet commented Nov 27, 2021

github-actions bot commented Nov 28, 2022

joakime commented Jul 1, 2020 •

edited

DenisDudinski commented Nov 23, 2021 •

edited