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]
