Good morning. I got the following log from my customer and I think it
demonstrates some problem with stale connection detection. The used versions
are httpclient:4.5.13 and httpcore:4.4.14. The interesting part is highlighted
in bold.
My understanding of the situation is the following. A connection with id 273 is
used and returned to the connection pool. PoolingHttpClientConnectionManager
uses default configuration of “setValidateAfterInactivity(2000)”. A minute
later the connection is requested from the pool. Connection 273 is checked for
staleness as suggested by “"http-outgoing-273 << \"[read] I/O error: Read timed
out\”"” message. But then that connection 273 is nevertheless leased out to the
client. Client tries to send data via that connection and, obviously, gets a
"end of stream” error.
How can it happen, that connection is checked for staleness and is still leased
out?
Kind regards
Nikita Salnikov-Tarnovski
{"timestamp":"2021-07-22T21:41:59.419Z","level":"DEBUG","message":"Connection
can be kept alive
indefinitely","logger":"com.signalfx.shaded.apache.http.impl.execchain.MainClientExec","thread":"signalfx-metrics-publisher","level_value":10000}
73
{"timestamp":"2021-07-22T21:41:59.419Z","level":"DEBUG","message":"Connection
[id: 273][route: {s}->https://ingest.signalfx.com:443
<https://ingest.signalfx.com/>] can be kept alive
indefinitely","logger":"com.signalfx.shaded.apache.http.impl.conn.PoolingHttpClientConnectionManager","thread":"signalfx-metrics-publisher","level_value":10000}
74
{"timestamp":"2021-07-22T21:41:59.419Z","level":"DEBUG","message":"http-outgoing-273:
set socket timeout to
0","logger":"com.signalfx.shaded.apache.http.impl.conn.DefaultManagedHttpClientConnection","thread":"signalfx-metrics-publisher","level_value":10000}
75
{"timestamp":"2021-07-22T21:41:59.419Z","level":"DEBUG","message":"Connection
released: [id: 273][route: {s}->https://ingest.signalfx.com:443][total
<https://ingest.signalfx.com:443][total> available: 1; route allocated: 1 of 2;
total allocated: 1 of
20]","logger":"com.signalfx.shaded.apache.http.impl.conn.PoolingHttpClientConnectionManager","thread":"signalfx-metrics-publisher","level_value":10000}
76
79
{"timestamp":"2021-07-22T21:42:59.325Z","level":"DEBUG","message":"Connection
request: [route: {s}->https://ingest.signalfx.com:443][total
<https://ingest.signalfx.com:443][total> available: 1; route allocated: 1 of 2;
total allocated: 1 of
20]","logger":"com.signalfx.shaded.apache.http.impl.conn.PoolingHttpClientConnectionManager","thread":"signalfx-metrics-publisher","level_value":10000}
80
{"timestamp":"2021-07-22T21:42:59.331Z","level":"DEBUG","message":"http-outgoing-273
<< \"[read] I/O error: Read timed
out\"","logger":"com.signalfx.shaded.apache.http.wire","thread":"signalfx-metrics-publisher","level_value":10000}
81
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"Connection
leased: [id: 273][route: {s}->https://ingest.signalfx.com:443][total
<https://ingest.signalfx.com:443][total> available: 0; route allocated: 1 of 2;
total allocated: 1 of
20]","logger":"com.signalfx.shaded.apache.http.impl.conn.PoolingHttpClientConnectionManager","thread":"signalfx-metrics-publisher","level_value":10000}
82
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"http-outgoing-273:
set socket timeout to
2000","logger":"com.signalfx.shaded.apache.http.impl.conn.DefaultManagedHttpClientConnection","thread":"signalfx-metrics-publisher","level_value":10000}
83
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"http-outgoing-273:
set socket timeout to
2000","logger":"com.signalfx.shaded.apache.http.impl.conn.DefaultManagedHttpClientConnection","thread":"signalfx-metrics-publisher","level_value":10000}
84
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"Executing
request POST /v2/datapoint
HTTP/1.1","logger":"com.signalfx.shaded.apache.http.impl.execchain.MainClientExec","thread":"signalfx-metrics-publisher","level_value":10000}
85
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"Target auth
state:
UNCHALLENGED","logger":"com.signalfx.shaded.apache.http.impl.execchain.MainClientExec","thread":"signalfx-metrics-publisher","level_value":10000}
86
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"Proxy auth
state:
UNCHALLENGED","logger":"com.signalfx.shaded.apache.http.impl.execchain.MainClientExec","thread":"signalfx-metrics-publisher","level_value":10000}
87
{"timestamp":"2021-07-22T21:42:59.333Z","level":"DEBUG","message":"http-outgoing-273
>> POST /v2/datapoint
HTTP/1.1","logger":"com.signalfx.shaded.apache.http.headers","thread":"signalfx-metrics-publisher","level_value":10000}
88
136
{"timestamp":"2021-07-22T21:42:59.418Z","level":"DEBUG","message":"http-outgoing-273
<< \"end of
stream\"","logger":"com.signalfx.shaded.apache.http.wire","thread":"signalfx-metrics-publisher","level_value":10000}
137
{"timestamp":"2021-07-22T21:42:59.418Z","level":"DEBUG","message":"http-outgoing-273:
Close
connection","logger":"com.signalfx.shaded.apache.http.impl.conn.DefaultManagedHttpClientConnection","thread":"signalfx-metrics-publisher","level_value":10000}
138
{"timestamp":"2021-07-22T21:42:59.422Z","level":"DEBUG","message":"http-outgoing-273:
Shutdown
connection","logger":"com.signalfx.shaded.apache.http.impl.conn.DefaultManagedHttpClientConnection","thread":"signalfx-metrics-publisher","level_value":10000}
139
{"timestamp":"2021-07-22T21:42:59.422Z","level":"DEBUG","message":"Connection
discarded","logger":"com.signalfx.shaded.apache.http.impl.execchain.MainClientExec","thread":"signalfx-metrics-publisher","level_value"
