How would you suggest we address this bug? 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?
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.auth.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.np.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]
