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 <[email protected]>; [email protected]
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 <[email protected]>
Sent: Tuesday, 19 April, 2022 7:03 PM
To: Robben, Bert <[email protected]>; JETTY user mailing list
<[email protected]>
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 <[email protected]> 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=http%3A%2F%2Fcometd.org%2F&data=05%7C01%7Cbert.robben%40fisglobal.com%7C6b9a6bc7a77240137ccf08da22268dbd%7Ce3ff91d834c84b15a0b418910a6ac575%7C0%7C0%7C637859846664537035%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=oE1wL9ZCbx2Iu1eMnfPUsWWvmdpMPONzKC5cAs5vZFA%3D&reserved=0
https://eur02.safelinks.protection.outlook.com/?url=http%3A%2F%2Fwebtide.com%2F&data=05%7C01%7Cbert.robben%40fisglobal.com%7C6b9a6bc7a77240137ccf08da22268dbd%7Ce3ff91d834c84b15a0b418910a6ac575%7C0%7C0%7C637859846664537035%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=OxP8lJHv%2BXNoGW%2BV3DMEVzAnO%2BXglP9ZnvbtzBSWZz4%3D&reserved=0
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
[email protected]
To unsubscribe from this list, visit
https://www.eclipse.org/mailman/listinfo/jetty-users
