| Re: [jetty-users] EXTERNAL: Re: jetty client delivers incomplete response without exception? |
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.Hi Greg,
Thanks for the answer. Regarding a solution, I don’t know what we can do.
We cannot set a content-length explicitly. The server is generating a very long reply based on many different resources. As such, the server doesn’t know what the content-length will be until after it has generated its huge reply. And we don’t want to do that because then the server needs to have the entire message in memory just to be able to set the header up front. Doing the expensive result computation twice, once to determine the size and a second time to send it over the network is stupid and wasteful of resources.
Jetty server itself is already using chunked transfer encoding. Our application logic didn’t decide to use chunked transfer encoding. It was jetty server that did this. Our logic server logic is a jax-rs resource that just writes to the jax-rs response outputstream. From the (incomplete) tcpdumps that we have, we can see that Jetty server (as expected) sets the transfer-encoding header.
0000 0a 58 0a 81 08 99 f2 ba 24 a1 f2 7f 08 00 45 00 .X......$.....E.
0010 22 c6 bb cc 40 00 3f 06 13 dc ac 1e 8a 51 0a 81 "...@.?......Q..
0020 08 99 1f 90 a9 09 5b 94 b3 52 87 f2 1c ec 80 18 ......[..R......
0030 00 ec 6c 42 00 00 01 01 08 0a ac d7 b7 b1 ac f4 ..lB............
0040 11 24 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f .$HTTP/1.1 200 O
0050 4b 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a K..Content-Type:
0060 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f 6a 73 6f application/jso
0070 6e 0d 0a 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f n..Access-Contro
0080 6c 2d 41 6c 6c 6f 77 2d 43 72 65 64 65 6e 74 69 l-Allow-Credenti
0090 61 6c 73 3a 20 74 72 75 65 0d 0a 41 63 63 65 73 als: true..Acces
00a0 73 2d 43 6f 6e 74 72 6f 6c 2d 41 6c 6c 6f 77 2d s-Control-Allow-
00b0 4d 65 74 68 6f 64 73 3a 20 47 45 54 2c 20 50 4f Methods: GET, PO
00c0 53 54 2c 20 50 55 54 2c 20 44 45 4c 45 54 45 2c ST, PUT, DELETE,
00d0 20 4f 50 54 49 4f 4e 53 2c 20 48 45 41 44 2c 20 OPTIONS, HEAD,
00e0 50 41 54 43 48 0d 0a 41 63 63 65 73 73 2d 43 6f PATCH..Access-Co
00f0 6e 74 72 6f 6c 2d 41 6c 6c 6f 77 2d 48 65 61 64 ntrol-Allow-Head
0100 65 72 73 3a 20 6f 72 69 67 69 6e 2c 20 63 6f 6e ers: origin, con
0110 74 65 6e 74 2d 74 79 70 65 2c 20 61 63 63 65 70 tent-type, accep
0120 74 2c 20 61 75 74 68 6f 72 69 7a 61 74 69 6f 6e t, authorization
0130 2c 20 69 64 65 6d 70 6f 74 65 6e 63 79 5f 6b 65 , idempotency_ke
0140 79 0d 0a 41 63 63 65 73 73 2d 43 6f 6e 74 72 6f y..Access-Contro
0150 6c 2d 41 6c 6c 6f 77 2d 4f 72 69 67 69 6e 3a 20 l-Allow-Origin:
0160 2a 0d 0a 54 72 61 6e 73 66 65 72 2d 45 6e 63 6f *..Transfer-Enco
0170 64 69 6e 67 3a 20 63 68 75 6e 6b 65 64 0d 0a 0d ding: chunked...
0180 0a 32 31 34 44 0d 0a 7b 22 63 75 73 74 6f 6d 65 .214D..{"custome
0190 72 50 61 79 6d 65 6e 74 53 74 61 74 75 73 52 65 rPaymentStatusRe
01a0 70 6f 72 74 56 30 37 44 6f 63 75 6d 65 6e 74 22 portV07Document"
01b0 3a 7b 22 63 75 73 74 6f 6d 65 72 50 61 79 6d 65 :{"customerPayme
01c0 6e 74 53 74 61 74 75 73 52 65 70 6f 72 74 22 3a ntStatusReport":
01d0 7b 22 67 72 6f 75 70 48 65 61 64 65 72 22 3a 7b {"groupHeader":{
01e0 22 6d 65 73 73 61 67 65 49 64 65 6e 74 69 66 69 "messageIdentifi
01f0 63 61 74 69 6f 6e 22 3a 22 49 44 22 2c 22 63 72 cation":"ID","cr
0200 65 61 74 69 6f 6e 44 61 74 65 54 69 6d 65 22 3a eationDateTime":
…
We tried to capture using tcpdump but gave up on that. Under this load we are producing that much data that we’re not fast enough to capture it. As a result, the dumped data that we have contains only a subset of all frames which makes it quite unusable. So we switched to jetty client logs as an alternative.
From how I understand the http spec for chunked transfer encoding, the stream should be ended with
last-chunk = 1*("0") [ chunk-extension ] CRLF
I don’t understand how that data can have come. So why is the client deciding that the stream is successfully closed?
Bert
From: Greg Wilkins <gregw@xxxxxxxxxxx>
Sent: Monday, 27 June, 2022 2:08 AM
To: JETTY user mailing list <jetty-users@xxxxxxxxxxx>
Cc: Robben, Bert <Bert.Robben@xxxxxxxxxxxxx>; Simone Bordet <sbordet@xxxxxxxxxxx>
Subject: 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