Thank you for your patience with me __ In the case where close is called and there is data still to be read, would it be possible to read to the end? Wouldn't that take care of the garbage problem? That would make the library more resilient to client vagaries.
On 7/25/18, 1:31 AM, "Oleg Kalnichevski" <[email protected]> wrote: On Wed, 2018-07-25 at 01:11 +0000, [email protected] wrote: > How would you suggest we address this bug? By kindly asking Jersey developers to fix it. > Right now it looks like if you use jersey (and possibly other > libraries as well) with httpcomponent it does not work properly with > both gzip and chunked encoding. > Can you help me understand why the client can not assume the > connection is safe for re-use if it does not read until the end? Why > is that a requirement? > If the closing chunk does not get consumed and the connection get re- used for another message exchange, on the next exchange the client gets garbage from the previous exchange instead of a valid response message. Oleg > Thanks for your help on this. > > > Can you help me understand why it is some imp > > On 7/24/18, 12:19 AM, "Oleg Kalnichevski" <[email protected]> wrote: > > On Mon, 2018-07-23 at 17:21 +0000, [email protected] wrote: > > Oleg, > > > > The data is properly formatted, and there is a closing chunk. > On > > further investigation it turns out that the problem is a > combination > > of both gzip and chunk encoding turned on. > > The gzip decoder knows exactly how many bytes it needs and > pulls > > exactly that number (at least our jersey version of it seems > to) -- > > so we never get to the closing block. Jersey then sends a close > to > > the file which causes it to close for real. Which is very much > not > > what we want. > > > > The question is whether it is legitimate for a client to send > close > > to a http connection using chunks without having read all the > way to > > the end. I would argue that it is. > > > > It is legitimate but if the consumer stops reading from the > content > stream without reading until the end of the stream the client > cannot > assume the connection to be safe for re-use. > > Oleg > > > > > On 7/20/18, 1:02 AM, "Oleg Kalnichevski" <[email protected]> > wrote: > > > > On Thu, 2018-07-19 at 01:07 +0000, [email protected] > wrote: > > > I am seeing a problem where ConnectionHolder.close() is > getting > > > called before ConnectionHolder.release() is called. This > > results in > > > immediately closing the connection even though we want to > keep > > it > > > around. > > > > > > This happens only with chunked responses. What appears to > > happen is > > > that jersey reads the last chunk with data and then > closes the > > > connection – which ultimately gets sent to > > ConnectionHolder.close(). > > > Since eof has not yet been found (we don’t seem to get > to the > > > nextChunk() call that reads the 0 chunk), it means the > > underlying > > > connection gets closed. > > > > > > > This issue has been reported and looked into on more than > one > > occasion. > > HttpClient behavior is correct. It is not safe to re-use a > > connection > > with a chunk coded response message whose data stream has > not > > been > > terminated by a closing chunk. > > > > Oleg > > > > > > > If I change this code > > > > > > @Override > > > public void close() throws IOException { > > > releaseConnection(false); > > > } > > > > > > To simply this: > > > > > > @Override > > > public void close() throws IOException { > > > releaseConnection(reusable); > > > } > > > > > > I no longer have the connection getting immediately > dropped. > > (This > > > does break a unit test, though). > > > > > > Here is some sample log output at debug level with the > problem: > > > > > > > > > tokenstatus 2018-07-17 21:12:46,282 +0000 DEBUG 117161 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > HTTP/1.1 > > > 200 OK > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Server: > > > nginx/1.13.10 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Date: > > > Tue, 17 Jul 2018 21:12:46 GMT > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Content- > > > Type: application/json;charset=UTF-8 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > > Transfer-Encoding: chunked > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > > Connection: keep-alive > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > RequestId: 16073adf3336513470aff4bcc23005d6 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > CorrelationId: f1f6c4cb-9f09-42a6-b5ce-8544592bd50b > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << X- > > > Content-Type-Options: nosniff > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << x- > > wily- > > > info: Clear guid=AA169DAC0ADB81C5151380A28398C79E > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << x- > > wily- > > > servlet: Encrypt1 > > > > > > hR/KG2GOR16aRfvv3/q1AY6IOmaQiRHSVfF4o38i8Nb6NeyR36CyvkJdrtOXs+Q6i7zEX > > > > > > S+Izr9EdU/xAf5ZhxHw0ow/QkacutvAiuKKILiB5+OqdEgjMxWr7r3IdRDJNdPklBSMvG > > > lPzS6DStuVPPHYlVqYfLeF5wTGvWuAivcjp7Io/wzYPActeNQCNkRr > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Cache- > > > Control: private, must-revalidate, max-age=3600 > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Expires: > > > Wed, 18 Jul 2018 09:12:45 GMT > > > > > > tokenstatus 2018-07-17 21:12:46,283 +0000 DEBUG 117162 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] headers [] - http-outgoing-5 > << > > Content- > > > Encoding: gzip > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] MainClientExec [] - > Connection can > > be > > > kept alive indefinitely > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "a[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > > "[0x3][0x0][0xc1]/[0xd7][0x14]U[\r][0x0][0x0][\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "0[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,284 +0000 DEBUG 117163 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "[\r][\n]" > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] > DefaultManagedHttpClientConnection > > [] - > > > http-outgoing-5: Close connection > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] MainClientExec [] - > Connection > > discarded > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] > PoolingHttpClientConnectionManager > > [] - > > > Connection released: [id: 5][route: {s}->https://kamaji.a > uth.ap > > i.np.a > > > c.playstation.net:443][total kept alive: 0; route > allocated: 3 > > of > > > 500; total allocated: 3 of 1000] > > > > > > tokenstatus 2018-07-17 21:12:46,285 +0000 DEBUG 117164 > > [511e5d7a- > > > 4e5d-496d-ac27-37778b0e1eff] wire [] - http-outgoing-5 << > > "[read] I/O > > > error: Socket is closed" > > > > > > And here is log output with the problem solved: > > > > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > HTTP/1.1 200 > > > OK > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Server: > > > nginx/1.13.10 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > Date: > > Thu, > > > 19 Jul 2018 00:32:19 GMT > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Content- > > > Type: application/json;charset=UTF-8 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Transfer- > > > Encoding: chunked > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Connection: > > > keep-alive > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > RequestId: > > > 49e6b565d40253cfc320547931f80a50 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > > CorrelationId: 9031d94b-133e-495b-aa99-39a5ffff7c65 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > X- > > Content- > > > Type-Options: nosniff > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > x- > > wily-info: > > > Clear guid=AFF3AC6D0ADB813826D1845C71D1DA71 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > x- > > wily- > > > servlet: Encrypt1 > > > > > > hR/KG2GOR16aRfvv3/q1AcDfNQfBP1AWkr5Dck/nEoqU5/Ft5cGKgUaFVMBigeSiwiPcI > > > > > > oX+2ikKbgkrgUodlPY7ogzMDnags9JMk3ktv98z33D2MCUqLopn132Nh2CW5UibmV9ShP > > > jWXFiphiHtL5GZ7ugYXVvCWt5z0kf7Dg55aD9Tou8pNiwZ0gzxvG5+ > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > Cache- > > > Control: private, must-revalidate, max-age=3600 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Expires: > > > Thu, 19 Jul 2018 12:31:30 GMT > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] headers [] - http-outgoing-13 << > > Content- > > > Encoding: gzip > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] MainClientExec [] - Connection > can be > > kept > > > alive indefinitely > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 31 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 139 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 8 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > > length: 0 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 6 return: 6 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 512 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 512 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 62 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "a[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > > > "[0x3][0x0][0x8][0x8a][0xc3][0xb8]6[\r][0x0][0x0][\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "0[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] wire [] - http-outgoing-13 << > > "[\r][\n]" > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] EofSensorInputStream [] - read() > off: 0 > > len: > > > 512 return: 10 > > > tokenstatus 2018-07-19 00:32:19,585 +0000 DEBUG 49853 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] MainClientExec [] - Connection > Holder; > > > releaseConnection; reusable: true > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > PoolingHttpClientConnectionManager [] - > > > Connection [id: 13][route: {s}->https://kamaji.auth.api.n > p.ac.p > > laysta > > > tion.net:443] can be kept alive indefinitely > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > DefaultManagedHttpClientConnection [] - > > http- > > > outgoing-13: set socket timeout to 0 > > > tokenstatus 2018-07-19 00:32:19,586 +0000 DEBUG 49854 > > [a1039839-20bb- > > > 4d1b-adaf-4950aef0e1ce] > PoolingHttpClientConnectionManager [] - > > > Connection released: [id: 13][route: {s}->https://kamaji. > auth.a > > pi.np. > > > ac.playstation.net:443][total kept alive: 11; route > allocated: > > 11 of > > > 500; total allocated: 11 of 1000] > > > > > > Note that I added some extra debug statements to get a > better > > idea of > > > the problem. In particular I added debug statements to > > > EofSensorInputStream.read() > > > > > > > ----------------------------------------------------------- > ------ > > ---- > > To unsubscribe, e-mail: [email protected] > > For additional commands, e-mail: [email protected] > > > > > > > > > > ------------------------------------------------------------- > -------- > > To unsubscribe, e-mail: [email protected] > > For additional commands, e-mail: [email protected] > > > > ----------------------------------------------------------------- > ---- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
