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.
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+Q6i7zEXS+Izr9EdU/xAf5ZhxHw0ow/QkacutvAiuKKILiB5+OqdEgjMxWr7r3IdRDJNdPklBSMvGlPzS6DStuVPPHYlVqYfLeF5wTGvWuAivcjp7Io/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.ac.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/Ft5cGKgUaFVMBigeSiwiPcIoX+2ikKbgkrgUodlPY7ogzMDnags9JMk3ktv98z33D2MCUqLopn132Nh2CW5UibmV9ShPjWXFiphiHtL5GZ7ugYXVvCWt5z0kf7Dg55aD9Tou8pNiwZ0gzxvG5+
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.playstation.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()
