InputStream blocks with Jetty HTTP client using an InputStreamResponseListener #2570

mpetzold · 2018-05-24T12:15:54Z

Im am using Jetty 9.4.8 HTTP client and want to write a stream of incoming data to a file. Currently I am using an InputStreamResponseListener and IOUtils.copy(..) writing to a FileOutputStream. I have also tried Files.copy().

InputStreamResponseListener streamResponseListener = new InputStreamResponseListener();

request.send(streamResponseListener);

if(streamResponseListener.get(5, TimeUnit.MINUTES).getStatus() == 200) {
    OutputStream outputStream = null;
    try {
        TMP_FILE.toFile().createNewFile();
        outputStream = new FileOutputStream(TMP_FILE.toFile());
        IOUtils.copy(inputStream, outputStream);
    } catch(IOException e) {
        this.getLogService().log(..)
    } finally {
        IOUtils.closeQuietly(inputStream);
        IOUtils.closeQuietly(outputStream);
    }

    // NOT REACHED IN CASE InputStream is BLOCKED FOR SOME REASON
}

InputStream is blocked in some cases when I use the InputStreamResponseListener object to handle the InputStream. IMHO this is a bug. I also think that onSuccess() should not be called by Jetty in case InputStream is not fully read or blocking.

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

joakime · 2018-05-24T12:51:23Z

Originally asked on stackoverflow.com at ...

https://stackoverflow.com/questions/50491316/copy-of-inputstream-blocks-with-jetty-http-client-using-an-inputstreamresponseli/50492873

sbordet · 2018-05-24T14:34:24Z

If you can reproduce, please attach DEBUG logs.

joakime · 2018-05-24T14:57:49Z

@mpetzold if you have no other logging frameworks present, you can start your test project with -Dorg.eclipse.jetty.LEVEL=DEBUG (jvm command line option)

mpetzold · 2018-05-24T15:35:17Z

One message which could be related. I will try to extract the other messages.

2018-05-24 17:31:34.991 DEBUG org.eclipse.jetty.io.WriteFlusher - ignored: WriteFlusher@3e6b079c{IDLE}->null
java.nio.channels.ClosedChannelException: null
at org.eclipse.jetty.io.WriteFlusher.onClose(WriteFlusher.java:507)
at org.eclipse.jetty.io.AbstractEndPoint.onClose(AbstractEndPoint.java:345)
at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:217)
at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:184)
at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:169)
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:196)
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:182)
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:161)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:289)
at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:149)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
at java.lang.Thread.run(Thread.java:748)

joakime · 2018-05-24T15:42:36Z

@mpetzold please include the entire DEBUG log.

The origin of that specific stacktrace...
https://github.com/eclipse/jetty.project/blob/09d40dc66507042f1cf865a89e7cacf431d2d584/jetty-io/src/main/java/org/eclipse/jetty/io/WriteFlusher.java#L504-L508

Also, since you are using SSL, what are your SslContextFactory settings?
Which specific version of Java are you using?
And are you using any non-standard encryption libraries (such as bouncy castle, conscrypt, etc..)?

mpetzold · 2018-05-24T15:44:11Z

openjdk version "1.8.0_171"

mpetzold · 2018-05-24T15:46:12Z

I currently do not set a SslContextFactory on client side.

mpetzold · 2018-05-24T15:48:22Z

once again, wget is working without any problems

joakime · 2018-05-24T15:50:05Z

wget ignores Content-Length and reads to socket EOL, not HTTP protocol EOL.
not a valid comparison with regards to EOL behavior.

joakime · 2018-05-24T15:51:42Z

Since you have SSL present in your stacktrace, you most definitely have an SslContextFactory present.

at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:289)
at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:149)

Do this, once your HttpClient is started, use HttpClient.getSslContextFactory().dump()

Are you using a 3rd party encryption library? (eg: Bouncy Castle)
And what OS?

mpetzold · 2018-05-24T15:52:10Z

server is sending a Content-Length header!

mpetzold · 2018-05-24T15:56:04Z

Ah, sorry: new SslContextFactory(true);

joakime · 2018-05-24T15:57:06Z

Even if the Content-Length header is present, it could be wrong value. Quite a common occurrence.

Eg:

You send 50 bytes, with a header Content-Length: 49. (this means your body content is larger then the Content-Length header)

In this scenario, byte 50 now belongs to the next response in the HTTP protocol.

You send 50 bytes, with a header Content-Length: 51. (this means your body content is smaller then the Content-Length header)

In this scenario, the protocol isn't finished, the client is still waiting on byte 51.
In this scenario, wget and curl will show you all 50 bytes (as they are 1 shot clients without a regard for persistence) and then exit as they (wget and curl) closed the Socket.
In this scenario, a client that honors the HTTP/1.1 protocol (with regards to persistence) will wait for the 51st byte, then likely idle timeout.

mpetzold · 2018-05-24T16:01:21Z

On server side I am also using Jetty and setting the Content-Length header of the response to InputStream.available(). My response headers:

Date: Wed, 23 May 2018 16:46:06 GMT
Content-Type: application/octet-stream
Content-Disposition: attachment; filename=".."
Content-Length: 613970044
Server: Jetty(9.4.8.v20171121)

The Content-Length matches the size the OS (on server side) tells me.

mpetzold · 2018-05-24T16:02:09Z

OS is a recent Linux on client and server side.

joakime · 2018-05-24T16:10:58Z

Large(-ish) file you got there.

While the underlying cause is important to discover, I should note that an old enhancement request on #929 could prove useful here.

Have you verified the server behavior thoroughly?

hash the file, on the server side, (sha1sum <filename>).
Use wget (or curl) to download the same file, then do the sha1sum <filename> on the downloaded file on your client side.
Are the hashes the same?

The response headers you posted don't seem to be the ones that would be produced by Jetty's own ResourceService / DefaultServlet static file serving, so it seems that your server side is doing the file serving using your own code.

mpetzold · 2018-05-24T16:12:42Z

According to filesystem on client side I can also confirm that all bytes are received by the client and size matches Content-Length.

mpetzold · 2018-05-24T16:16:12Z

Exactly. I am using Jetty+Jersey on server side:

InputStream inputStream = artifact.openStream();
return Response.ok(new StreamingOutput() {
	@Override
	public void write(OutputStream outputStream) throws IOException,WebApplicationException {
		try {
			IOUtils.copy(inputStream, outputStream);
		} catch(IOException e) {
			// logging ...
		} finally {
			IOUtils.closeQuietly(inputStream);
			IOUtils.closeQuietly(outputStream);
		}
	}
}, MediaType.APPLICATION_OCTET_STREAM).header("Content-Length", inputStream.available()).header("Content-Disposition", "attachment; filename=\"" + artifact.getFilename() + "\"").build();

mpetzold · 2018-05-24T16:20:10Z

sha1sum is identical on client and on server side. However, this time I cannot find "org.eclipse.jetty.io.WriteFlusher - ignored" in the log output. But the InputStream is still blocking.

joakime · 2018-05-24T16:22:10Z

Do you have that client side DEBUG log yet? (the final minute of logs should be sufficient)

mpetzold · 2018-05-24T16:28:06Z

Please find the log file from client side attached. This is only the last part because it is very long for this large file. I am not 100% sure if this reflects the end, please let me know if you need more.

log.txt

joakime · 2018-05-24T16:32:10Z

There's a lot of unrelated things going on in this log, but the log doesn't contain the thread-id that would help to filter out the unrelated activity and correlate the related events together.
Can you add the thread-id or thread-name to your logging output?
Or run a simplified test that doesn't include the unrelated traffic (eg:websocket)?

mpetzold · 2018-05-24T16:34:15Z

This is the related request:

2018-05-24 18:15:19.542 DEBUG o.eclipse.jetty.client.HttpReceiver - Request/Response succeeded: Result[HttpRequest[GET /my/path/to/artifact HTTP/1.1]@21989fe2 > HttpResponse[HTTP/1.1 200 OK]@33044a59] null

joakime · 2018-05-24T21:24:39Z

I've created a small project to attempt to replicate this report.

https://github.com/jetty-project/jetty-jersey-large-file

This is jetty + jersey on the server side, using your StreamingOutput facility.
And jetty-client on the client side.

Attempted with a 1.7GB file with no issues (so far).

Output of server:

16:19:15.764 [main] INFO  org.eclipse.jetty.util.log - Logging initialized @395ms to org.eclipse.jetty.util.log.Slf4jLog
16:19:15.889 [main] INFO  demo.server.Artifacts - Artifacts base: C:\Users\joakim\Downloads\isos
16:19:15.945 [main] INFO  org.eclipse.jetty.server.Server - jetty-9.4.10.v20180503; built: 2018-05-03T15:56:21.710Z; git: daa59876e6f384329b122929e70a80934569428c; jvm 1.8.0_162-b12
16:19:15.981 [main] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@11438d26{/,null,AVAILABLE}
16:19:16.144 [main] INFO  o.e.jetty.server.AbstractConnector - Started ServerConnector@6043cd28{HTTP/1.1,[http/1.1]}{0.0.0.0:9090}
16:19:16.144 [main] INFO  org.eclipse.jetty.server.Server - Started @780ms

Output of client:

16:19:21.762 [main] INFO  org.eclipse.jetty.util.log - Logging initialized @391ms to org.eclipse.jetty.util.log.Slf4jLog
Using HttpClient v9.4.10.v20180503
Requesting: http://localhost:9090/largefile/Fedora-Workstation-Live-x86_64-28-1.1.iso
Downloaded http://localhost:9090/largefile/Fedora-Workstation-Live-x86_64-28-1.1.iso
Destination: target\tmp4419531979773673394.dl (1,787,822,080 bytes)

Next step is to add SSL to the server side and see if anything changes.

joakime · 2018-05-24T21:41:33Z

Added SSL to the example project - jetty-project/jetty-jersey-large-file@3b91354

The results are the same.

Server side:

16:37:56.412 [main] INFO  org.eclipse.jetty.util.log - Logging initialized @374ms to org.eclipse.jetty.util.log.Slf4jLog
16:37:56.556 [main] INFO  demo.server.Artifacts - Artifacts base: C:\Users\joakim\Downloads\isos
16:37:56.594 [main] INFO  org.eclipse.jetty.server.Server - jetty-9.4.10.v20180503; built: 2018-05-03T15:56:21.710Z; git: daa59876e6f384329b122929e70a80934569428c; jvm 1.8.0_162-b12
16:37:56.632 [main] INFO  o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@7d70d1b1{/,null,AVAILABLE}
16:37:56.781 [main] INFO  o.e.jetty.server.AbstractConnector - Started ServerConnector@1a3869f4{HTTP/1.1,[http/1.1]}{0.0.0.0:9090}
16:37:56.796 [main] INFO  o.e.jetty.util.ssl.SslContextFactory - x509=X509@ed9d034(mykey,h=[],w=[]) for SslContextFactory@6121c9d6[provider=null,keyStore=file:///C:/code/jetty/github/jetty-jersey-large-file/target/classes/keystore,trustStore=null]
16:37:57.119 [main] INFO  o.e.jetty.server.AbstractConnector - Started ServerConnector@543e710e{SSL,[ssl, http/1.1]}{0.0.0.0:9443}
16:37:57.119 [main] INFO  org.eclipse.jetty.server.Server - Started @1085ms

Client side:

16:38:01.039 [main] INFO  org.eclipse.jetty.util.log - Logging initialized @372ms to org.eclipse.jetty.util.log.Slf4jLog
16:38:01.198 [main] INFO  o.e.jetty.util.ssl.SslContextFactory - x509=X509@271053e1(mykey,h=[],w=[]) for SslContextFactory@589838eb[provider=null,keyStore=file:///C:/code/jetty/github/jetty-jersey-large-file/target/classes/keystore,trustStore=null]
Using HttpClient v9.4.10.v20180503
Requesting: https://localhost:9443/largefile/Fedora-Workstation-Live-x86_64-28-1.1.iso
Downloaded https://localhost:9443/largefile/Fedora-Workstation-Live-x86_64-28-1.1.iso
Destination: target\tmp3357699038738973754.dl (1,787,822,080 bytes)

@mpetzold can you fork that example project and replicate the issue you are seeing? (This minimal example plus a reproduction would go a long way to solve this issue)

mpetzold · 2018-05-25T08:27:40Z

Could this be related to an open web socket connection to the same server? I am using the same HttpClient instance for both, actually several, connections.

mpetzold · 2018-05-25T09:21:42Z

Also on server side I am using one web server instance to handle HTTP and WebSocket requests. I am using a context handler collection for several endpoints.

mpetzold · 2018-05-29T12:16:57Z

InputStreamResponseListener is blocking at line 318 at lock.wait(). It seems that onSuccess() is not (!) called, however, onComplete() is called and returnes.

joakime · 2018-05-29T12:44:58Z

Long term link to code being referenced by @mpetzold

https://github.com/eclipse/jetty.project/blob/d3b81e53721f94e06b722cb8c75e7129c8654f2f/jetty-client/src/main/java/org/eclipse/jetty/client/util/InputStreamResponseListener.java#L302-L319

joakime · 2018-05-29T12:46:37Z

@mpetzold that's normal.

The problem isn't that lock, its somewhere else.
Either in the actual data being sent, or the HTTP protocol, or the network layer, or the server side behavior, or the client side behavior.
Not the lock itself.

Can you replicate with the example codebase?

Also, websocket on the same server/client will have no impact on this.

mpetzold · 2018-05-29T12:48:04Z

I did not test the example codebase. It is too far away from my complex implementation. I think it could be about the WebSocket connection. However, I still need to disable this and test.

mpetzold · 2018-05-29T12:48:52Z

@joakime what could the problem with the data be?

joakime · 2018-05-29T12:52:43Z

One niggle with your codebase.

}, MediaType.APPLICATION_OCTET_STREAM).header("Content-Length", inputStream.available()) ...

The use of inputStream.available() here for Content-Length is wrong, that's not what available is for.

InputStream.available() is an estimate for the next potential read (and the next read only), it can also be zero.
The most common implementation in the JDK (but not the only one) It works by looking at buffers internally and if there is a buffer, and it has content that is unread, then it returns the number of bytes on that one buffer that is capable of being read.
Most JDK classes don't even implement InputStream.available().

https://docs.oracle.com/javase/8/docs/api/java/io/InputStream.html#available--

Also note that InputStream.available() is even allowed to block to get its answer.

For your example codebase, either use the artifact file size properly, or don't set a Content-Length.

mpetzold · 2018-05-29T12:52:44Z

Ok. Also blocking with WebSocket connection disabled.

joakime · 2018-05-29T12:54:07Z

Something else.

The link to the InputStreamResponseListener that you just referenced is for the code that processes Transfer-Encoding: chunked.
If your server actually sent the Content-Length header, then Transfer-Encoding: chunked wouldn't be used.

mpetzold · 2018-05-29T12:56:42Z

Maybe this is a bug then. I am sending Content-Length header. Checked it with an HTTP client tool.

Thanks for the hint about available(). I was aware about this, however, in my case it seems to give the correct size of the artifact.

joakime · 2018-05-29T12:58:45Z

Is your Server code sending both a Content-Length header and Transfer-Encoding header?
If so, then you have a RFC7230 violation.

joakime · 2018-05-29T13:00:26Z

If your server code doesn't set a Content-Length header and starts writing, then it should default to Transfer-Encoding: chunked mode.

mpetzold · 2018-05-29T13:15:26Z

Using actual file size (File.length()) instead of InputStream.available(). Size of file in Linux filesystem (ls -l): 613971248

Response headers (according to Chrome Restlet HTTP client):

Date: Tue, 29 May 2018 13:11:37 GMT
Content-Type: application/octet-stream
Content-Disposition: attachment; filename="myfile.deb"
Content-Length: 613971248
Server: Jetty(9.4.8.v20171121)

@joakime So why is it using code that processes Transfer-Encoding: chunked?

mpetzold · 2018-05-29T14:13:44Z

I am also checking for the response code, as suggested in you examples:
if(streamingResponse.getStatus().equals(Response.Status.OK))
This is the case for simple streaming response. In case of a chunked response it should be:
if(streamingResponse.getStatus().equals(Response.Status.PARTIAL_CONTENT))
And of course far more complex implementation.

mpetzold · 2018-05-30T06:56:17Z

Found the problem. I am overriding onSuccess(). Thus this method is not called in InputStreamResponseListener. I'm very sorry for wasting your time. I could have realized earlier.

However, I would recommend a clean API for streaming response. I was working with the class just as with the other response handlers (all clean interfaces). There could be something like:

org.eclipse.jetty.client.api

interface Response.Listener {
    onStreaming(InputStream inputStream);
}

sbordet · 2018-05-30T08:07:45Z

@mpetzold can you clarify what you mean by:

I am overriding onSuccess(). Thus this method is not called in InputStreamResponseListener.

onSuccess() should be called and if not, it's a bug.

mpetzold · 2018-05-30T08:24:12Z

I am using an internal API similar to the one suggested in my last comment. I implemented a proxy object extending the InputStreamResponseListener class to handle the events. There I override all methods in order to call each method for my API. I forgot to call super.onSuccess() in order to keep everything in InputStreamResponseListener working. I was somehow thinking it was an interface.

This is my API on the user side:

new StreamingResponseListener() {			
    @Override
    public void onSuccess(Request request, Response response) {
        // ...
    }
				
    @Override
    public void onStreaming(InputStream inputStream) {
        // ...
    }
}

joakime assigned sbordet May 24, 2018

mpetzold closed this as completed May 30, 2018

noblepaul mentioned this issue Nov 23, 2021

upgrade jetty to 9.4.44.v20210927 fullstorydev/lucene-solr#121

Closed

InputStream blocks with Jetty HTTP client using an InputStreamResponseListener #2570

InputStream blocks with Jetty HTTP client using an InputStreamResponseListener #2570

Comments

mpetzold commented May 24, 2018 • edited Loading

joakime commented May 24, 2018

sbordet commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 24, 2018 • edited Loading

joakime commented May 24, 2018

mpetzold commented May 24, 2018

joakime commented May 24, 2018

joakime commented May 24, 2018

mpetzold commented May 25, 2018 • edited Loading

mpetzold commented May 25, 2018

mpetzold commented May 29, 2018 • edited Loading

joakime commented May 29, 2018

joakime commented May 29, 2018

mpetzold commented May 29, 2018

mpetzold commented May 29, 2018 • edited Loading

joakime commented May 29, 2018

mpetzold commented May 29, 2018

joakime commented May 29, 2018

mpetzold commented May 29, 2018

joakime commented May 29, 2018

joakime commented May 29, 2018

mpetzold commented May 29, 2018 • edited Loading

mpetzold commented May 29, 2018 • edited Loading

mpetzold commented May 30, 2018 • edited Loading

sbordet commented May 30, 2018

mpetzold commented May 30, 2018 • edited Loading

mpetzold commented May 24, 2018 •

edited

Loading

mpetzold commented May 24, 2018 •

edited

Loading

mpetzold commented May 25, 2018 •

edited

Loading

mpetzold commented May 29, 2018 •

edited

Loading

mpetzold commented May 29, 2018 •

edited

Loading

mpetzold commented May 29, 2018 •

edited

Loading

mpetzold commented May 29, 2018 •

edited

Loading

mpetzold commented May 30, 2018 •

edited

Loading

mpetzold commented May 30, 2018 •

edited

Loading