Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] EXTERNAL: Re: jetty client delivers incomplete response without exception?

Bert,

In the log I can see that jetty reads -1 from the connection:

[2022-06-24 13:59:42,844] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read -1 bytes in RetainableByteBuffer@7981e286{DirectByteBuffer@31b1f4ee[p=0,l=0,c=16384,r=0]={<<<>>>","supple...ringRef},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,ISHUT,fill=-,flush=-,to=200/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1438806 of -1}]]

So this is a little strange, as the server was "savagely killed" and a more exceptional end to the connection could be expected.  However, this is entirely dependent on many factors such as intermediaries, routers, network setup and perhaps even the exact state of the server when it was savagely killed.    Either way, it is beyond Jetty's control how the socket layer presents the failure, and in this case the failure looks like a normal EOF.

If I'm reading the log correctly, the transfer is being done with EOF_CONTENT mode, so an orderly EOF is taken to be the real end of the content.    Thus jetty has been told the response ends with EOF and it has seen a valid EOF, so it thinks that is the content and has no way to know that it is not.  This is a flaw of the HTTP protocol that uses EOF for message framing.

The solution is to just not use EOF for message framing.   Either set a content length or you can try hinting for the server to use chunked transfer encoding (by setting `Transfer-Encoding: chunked` in the response headers).

It may also be worthwhile to try to get a tcpdump of such a conversation to see exactly why a clean -1 is being read for that connection... or even an strace of the client process to verify a -1 is really being read.

regards















On Sat, 25 Jun 2022 at 00:42, Robben, Bert via jetty-users <jetty-users@xxxxxxxxxxx> wrote:
It's been a while since my last email on this, but we've finally been able to reproduce it with full jetty client debug logs.

We're running with Jetty 9.4.46.v20220331.

To recap:
(1) client makes a GET request on server
(2) server returns a huge response (several megabytes big)
(3) during this response, the server is savagely killed (kill -9)
(4) for most ongoing requests, client sees this as an EOFexception (which is to be expected and which we are happy with), but some ongoing requests terminate with an http 200 OK while having an incomplete response body.

Here's some output of a request of which the actual response is only 1438806 bytes while the expected response should be much bigger.

...
[2022-06-24 13:59:42,638] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Parse complete=false, RetainableByteBuffer@2d4c7ad4{DirectByteBuffer@36fe710a[p=16229,l=16229,c=16384,r=0]={,"account...","stat<<<>>>dIdentifi...2.529Z"},r=1} HttpParser{s=EOF_CONTENT,1438806 of -1}
[2022-06-24 13:59:42,641] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read 0 bytes in RetainableByteBuffer@2d4c7ad4{DirectByteBuffer@36fe710a[p=0,l=0,c=16384,r=0]={<<<>>>,"account...2.529Z"},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,OPEN,fill=-,flush=-,to=5/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1438806 of -1}]]
[2022-06-24 13:59:42,844] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Parse complete=false, RetainableByteBuffer@7981e286{DirectByteBuffer@31b1f4ee[p=0,l=0,c=16384,r=0]={<<<>>>","supple...ringRef},r=1} HttpParser{s=EOF_CONTENT,1438806 of -1}
[2022-06-24 13:59:42,844] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read -1 bytes in RetainableByteBuffer@7981e286{DirectByteBuffer@31b1f4ee[p=0,l=0,c=16384,r=0]={<<<>>>","supple...ringRef},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,ISHUT,fill=-,flush=-,to=200/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1438806 of -1}]]
[2022-06-24 13:59:42,849] [ERROR] [] [c.c.n.t.p.s.StreamingWriterScenario] [] - Received data 1438806 in 6_3 is too small. Expecting to be at least 1504200

Note that for this response there is no java.io.EOFException, which we do see for other responses (in the same logs).

The logs for this particular request/response look like

[2022-06-24 13:59:42,319] [DEBUG] [] [o.e.jetty.client.HttpDestination] [] - Queued HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.
1]@264a9253 for HttpDestination[http://test-product.na-test-product.svc:8080]@13476508,queue=1,pool=RoundRobinConnectionPool@7e823bd[c=0/45/100000,a=9,i=36,q=1]
[2022-06-24 13:59:42,320] [DEBUG] [] [o.e.jetty.client.HttpDestination] [] - Processing exchange HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming
-writer/customerCreditTransfers HTTP/1.1]@264a9253[PENDING/null] res=HttpResponse[null 0 null]@2e6dea5e[PENDING/null]} on HttpConnectionOverHTTP@4bf7cbf::SocketChann
elEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,OPEN,fill=FI,flush=-,to=6921/0}{io=1/1,kio=1,kro=8}->HttpConnectionO
verHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=null)[send=Http
SenderOverHTTP@318845ec(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=IDLE,failure=null)[HttpParser{s=STA
RT,0 of -1}]] of HttpDestination[http://test-product.na-test-product.svc:8080]@13476508,queue=0,pool=RoundRobinConnectionPool@7e823bd[c=0/45/100000,a=10,i=35,q=0]
[2022-06-24 13:59:42,320] [DEBUG] [] [o.e.jetty.client.HttpConnection] [] - Normalizing true HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfer
s HTTP/1.1]@264a9253
[2022-06-24 13:59:42,320] [DEBUG] [] [org.eclipse.jetty.client.HttpChannel] [] - HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customer
CreditTransfers HTTP/1.1]@264a9253[PENDING/null] res=HttpResponse[null 0 null]@2e6dea5e[PENDING/null]} associated true to HttpChannelOverHTTP@3d9c7d7e(exchange=HttpE
xchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[PENDING/null] res=HttpResponse[null 0 null]@2e6dea5
e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=IDLE,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=IDLE,fai
lure=null)[HttpParser{s=START,0 of -1}]]
[2022-06-24 13:59:42,320] [DEBUG] [] [org.eclipse.jetty.client.HttpSender] [] - Request begin HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfe
rs HTTP/1.1]@264a9253
[2022-06-24 13:59:42,320] [DEBUG] [] [org.eclipse.jetty.client.HttpSender] [] - Request headers HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTrans
fers HTTP/1.1]@264a9253
[2022-06-24 13:59:42,321] [DEBUG] [] [org.eclipse.jetty.client.HttpSender] [] - Request committed HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTra
nsfers HTTP/1.1]@264a9253
[2022-06-24 13:59:42,321] [DEBUG] [] [org.eclipse.jetty.client.HttpSender] [] - Request success HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTrans
fers HTTP/1.1]@264a9253
[2022-06-24 13:59:42,321] [DEBUG] [] [o.eclipse.jetty.client.HttpExchange] [] - Terminated request for HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/str
eaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[null 0 null]@2e6dea5e[PENDING/null]}, result: null
[2022-06-24 13:59:42,321] [DEBUG] [] [org.eclipse.jetty.client.HttpSender] [] - Terminating request HttpRequest[GET /test-product/v1/streaming-writer/customerCreditT
ransfers HTTP/1.1]@264a9253
[2022-06-24 13:59:42,337] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read 16384 bytes in RetainableByteBuffer@2d4c7ad4{DirectByteBuffer@36fe710a[p=0,l=163
84,c=16384,r=16384]={<<<HTTP/1.1 200 OK\r\nContent-...2E.1.45","transactionSt>>>},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-te
st-product.svc/172.30.166.114:8080,OPEN,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-p
roduct.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/custo
merCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[null 0 null]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLET
ED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
...
More logs from httpReceiver where it reads more and more stuff
...
[2022-06-24 13:59:42,636] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read 16229 bytes in RetainableByteBuffer@2d4c7ad4{DirectByteBuffer@36fe710a[p=0,l=16229,c=16384,r=16229]={<<<,"accountServicerReferenc...ionStatus":"PDNG","stat>>>dIdentifi...2.529Z"},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,OPEN,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1422577 of -1}]]
[2022-06-24 13:59:42,641] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read 0 bytes in RetainableByteBuffer@2d4c7ad4{DirectByteBuffer@36fe710a[p=0,l=0,c=16384,r=0]={<<<>>>,"account...2.529Z"},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,OPEN,fill=-,flush=-,to=5/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1438806 of -1}]]
[2022-06-24 13:59:42,844] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Read -1 bytes in RetainableByteBuffer@7981e286{DirectByteBuffer@31b1f4ee[p=0,l=0,c=16384,r=0]={<<<>>>","supple...ringRef},r=1} from SocketChannelEndPoint@6729d2cd{l=/10.129.8.239:52852,r=test-product.na-test-product.svc/172.30.166.114:8080,ISHUT,fill=-,flush=-,to=200/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@4bf7cbf(l:/10.129.8.239:52852 <-> r:test-product.na-test-product.svc/172.30.166.114:8080,closed=false)=>HttpChannelOverHTTP@3d9c7d7e(exchange=HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[PENDING/null]})[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=CONTENT,failure=null)[HttpParser{s=EOF_CONTENT,1438806 of -1}]]
[2022-06-24 13:59:42,849] [DEBUG] [] [o.eclipse.jetty.client.HttpExchange] [] - Terminated response for HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[TERMINATED/null]}, result: Result[HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253 > HttpResponse[HTTP/1.1 200 OK]@2e6dea5e] null
[2022-06-24 13:59:42,849] [DEBUG] [] [org.eclipse.jetty.client.HttpChannel] [] - HttpExchange@47cdff18{req=HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@2e6dea5e[TERMINATED/null]} disassociated true from HttpChannelOverHTTP@3d9c7d7e(exchange=null)[send=HttpSenderOverHTTP@318845ec(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@4ead8de6{s=START}],recv=HttpReceiverOverHTTP@67bb9144(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
[2022-06-24 13:59:42,864] [DEBUG] [] [o.eclipse.jetty.client.HttpReceiver] [] - Request/Response succeeded: Result[HttpRequest[GET /test-product/v1/streaming-writer/customerCreditTransfers HTTP/1.1]@264a9253 > HttpResponse[HTTP/1.1 200 OK]@2e6dea5e] null, notifying [org.eclipse.jetty.client.util.InputStreamResponseListener@68aa8699]


I'd appreciate any help with this as this feels to me like a bug somewhere in Jetty client.

If you need the full logs, please let me know and I can send you the full logs (6 megs gzipped).

Bert

-----Original Message-----
From: Robben, Bert
Sent: Wednesday, 20 April, 2022 8:27 AM
To: Simone Bordet <sbordet@xxxxxxxxxxx>; jetty-users@xxxxxxxxxxx
Subject: RE: [jetty-users] EXTERNAL: Re: jetty client delivers incomplete response without exception?

> The client knows how many bytes from the `Content-Length` header; if it sees less, it produces an EOF exception.
> If the content is chunked, it expects the terminating chunk; if it does not see it, it produces an EOF exception.

Our server-side resource does not set the Content-Length header. It doesn't do this because it has no idea up-front what the size will be. It traverses a huge data structure and writes that in json-form to the response stream. The data structure is never in-memory in its entirety because the total size can go > 1 Gb. As such, the resource also writes the json piece-by-piece.

In pseudo-code, that would go more or less like this

response.write('[');
for (int part = 0; part < someBigNumber; part++) {
   if (part != 0) response.write(',');
   objectMapper.writeAsJson(producePart(part), response); } response.write(']'); response.close();

The real code is more complicated than shown here because it does all of this asynchronously, but it should still give a good idea of what is going on.

I can imagine that if the connection is cut somewhere in the middle of some tcp package that we'll see this as an IOEXception. If the connection is cut at a moment that no data is being transferred (because the server-side resource is e.g. still producing some part) then I can understand that the client is not aware of a problem and doesn't throw.

Would that make sense?

Thanks,

Bert

-----Original Message-----
From: Simone Bordet <sbordet@xxxxxxxxxxx>
Sent: Tuesday, 19 April, 2022 7:03 PM
To: Robben, Bert <Bert.Robben@xxxxxxxxxxxxx>; JETTY user mailing list <jetty-users@xxxxxxxxxxx>
Subject: Re: [jetty-users] EXTERNAL: Re: jetty client delivers incomplete response without exception?

Hi,

On Tue, Apr 19, 2022 at 9:08 AM Robben, Bert <Bert.Robben@xxxxxxxxxxxxx> wrote:
>
> Hi,
>
> I know that the response was incomplete because the test expects a certain amount of bytes (it knows this because it knows what the server should be returning) and it gets only a fraction of the expected amount. In other words, the client received some response, but only a part of it.
>
> This looks to be very much a race condition. This test is part of our daily build so it runs a lot. But this particular failure I've seen only once so far. So I'm afraid I cannot reproduce.
>
> How does the http client know that more data is supposed to come? I can understand that it detects that the connection is closed, but how can it make a difference between "this is it, you got your complete response" and "there is a problem, server needed to send more stuff but there was for some reason a connection issue"?
>

The client knows how many bytes from the `Content-Length` header; if it sees less, it produces an EOF exception.
If the content is chunked, it expects the terminating chunk; if it does not see it, it produces an EOF exception.

So yes could be a Jetty bug, or an application bug (e.g. your application expects just one chunk of content, but when it receives 2 it loses one), that's why we would need some evidence in the form of DEBUG logs.

> We do run in k8s, so there are some hops (k8s services) in between the jetty client and the jetty web server. I have no idea if these can also play a role here.

It could. We don't have a particularly good experience with k8s, although it seems more stable with TCP than with UDP.
Again, no way to tell unless there is evidence (although this would require network traces to be sure).

--
Simone Bordet
----
https://eur02.safelinks.protection.outlook.com/?url="">
https://eur02.safelinks.protection.outlook.com/?url="">
Developer advice, training, services and support from the Jetty & CometD experts.
The information contained in this message is proprietary and/or confidential. If you are not the intended recipient, please: (i) delete the message and all copies; (ii) do not disclose, distribute or use the message in any manner; and (iii) notify the sender immediately. In addition, please be aware that any message addressed to our domain is subject to archiving and review by persons other than the intended recipient. Thank you.
_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To unsubscribe from this list, visit https://www.eclipse.org/mailman/listinfo/jetty-users


--
Greg Wilkins <gregw@xxxxxxxxxxx> CTO http://webtide.com

Back to the top