Re: Stale connection still leased and used

[Oleg Kalnichevski]

On 8/2/2021 10:43 AM, Nikita Salnikov-Tarnovski wrote:
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. 

Hi Nikita

To the contrary a timeout on a read operation basically means the 
connection is still perfectly valid (not stale), at least as far as JRE 
is concerned. Otherwise a socket exception would have occurred.

Oleg


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"


---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscr...@hc.apache.org
For additional commands, e-mail: httpclient-users-h...@hc.apache.org