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]
