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. 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.api.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.playsta > 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.api.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]
