You are viewing a plain text version of this content. The canonical link for it is here.
Posted to httpclient-users@hc.apache.org by Nikita Salnikov-Tarnovski <ns...@splunk.com.INVALID> on 2021/08/02 08:43:19 UTC
Stale connection still leased and used
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"
Re: Stale connection still leased and used
Posted by Nikita Salnikov-Tarnovski <ns...@splunk.com.INVALID>.
Got it, thank you for the explanation :)
Nikita
> On 3. Aug 2021, at 00:17, Oleg Kalnichevski <ol...@apache.org> wrote:
>
> [ External sender. Exercise caution. ]
>
>
> On 8/2/2021 8:44 PM, Nikita Salnikov-Tarnovski wrote:
>> I am sorry if my response seemed rude. That was not my intention.
>> I am now confused what does it mean for a connection to be stale? Am I correct in thinking that when server closes a connection then it becomes stale? How can reading from a connection detect this situation? If not read timeout that what signals it?
>> Nikita
>
> The main limitation of the classic i/o is that network sockets can react to events only when blocked in an i/o operation. Persistent connections while kept idle in the connection pool can become half-closed or reset by the opposite endpoint without the local endpoint realizing it. The only way to find out whether or not the connection is still valid is by performing an i/o operation on it. This is percisely what the stale connection check is about. It is a very short read operation (~ 1 ms) that either times out if that the socket is still valid, returns immediately with -1 if the socket has been half-closed or causes a socket exception if the socket has been reset.
>
> Hope this helps
>
> Oleg
>
>
>>> On 2. Aug 2021, at 20:27, Oleg Kalnichevski <ol...@apache.org> wrote:
>>>
>>> [ External sender. Exercise caution. ]
>>>
>>> On Mon, 2021-08-02 at 15:52 +0300, Nikita Salnikov-Tarnovski wrote:
>>>> Thank you for you reply. I have debug some more and unfortunately
>>>> have to disagree with you. I currently observer the following:
>>>>
>>>
>>> You are very welcome to disagree with me but it is not going to change
>>> the way HttpClient validates persistent connections.
>>>
>>>
>>>> At some point during application run this line throws a
>>>> "java.net.SocketTimeoutException: Read timed out"
>>>> https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81
>>>> <https://github.com/apache/httpcomponents-
>>>> client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/
>>>> main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#
>>>> L81>
>>>>
>>>> This results in "[read] I/O error: Read timed out\” being written to
>>>> logs.
>>>> That SocketTimeoutException is then propagated to here:
>>>> https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364
>>>> <https://github.com/apache/httpcomponents-
>>>> core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/
>>>> java/org/apache/http/impl/BHttpConnectionBase.java#L364>
>>>>
>>>> after which `isStale` method returns false. Thus we have a
>>>> connection, which threw SocketTimeoutException but is not considered
>>>> as stale. From your reply to my previous email I assume that this
>>>> exception should mean that connection is stale, right?
>>>
>>>
>>> No, it absolutely should not. That basically means the connection was
>>> unable to produce any input data within one ms time period but
>>> otherwise was perfectly valid.
>>>
>>> Oleg
>>>
>>>>
>>>> Nikita
>>>>
>>>>> On 2. Aug 2021, at 12:50, Oleg Kalnichevski <ol...@apache.org>
>>>>> wrote:
>>>>>
>>>>> [ External sender. Exercise caution. ]
>>>>>
>>>>>
>>>>> 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.exec
>>>>>> chain.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.DefaultMan
>>>>>> agedHttpClientConnection","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.PoolingH
>>>>>> ttpClientConnectionManager","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.PoolingH
>>>>>> ttpClientConnectionManager","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.PoolingH
>>>>>> ttpClientConnectionManager","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.Default
>>>>>> ManagedHttpClientConnection","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.Default
>>>>>> ManagedHttpClientConnection","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.execchai
>>>>>> n.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.exec
>>>>>> chain.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.exec
>>>>>> chain.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","thr
>>>>>> ead":"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.D
>>>>>> efaultManagedHttpClientConnection","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.D
>>>>>> efaultManagedHttpClientConnection","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.execcha
>>>>>> in.MainClientExec","thread":"signalfx-metrics-
>>>>>> publisher","level_value"
>>>>>
>>>>> -----------------------------------------------------------------
>>>>> ----
>>>>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>>>>> For additional commands, e-mail:
>>>>> httpclient-users-help@hc.apache.org
>>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>>> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org <ma...@hc.apache.org>
>> For additional commands, e-mail: httpclient-users-help@hc.apache.org <ma...@hc.apache.org>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org <ma...@hc.apache.org>
> For additional commands, e-mail: httpclient-users-help@hc.apache.org <ma...@hc.apache.org>
Re: Stale connection still leased and used
Posted by Oleg Kalnichevski <ol...@apache.org>.
On 8/2/2021 8:44 PM, Nikita Salnikov-Tarnovski wrote:
> I am sorry if my response seemed rude. That was not my intention.
>
> I am now confused what does it mean for a connection to be stale? Am I correct in thinking that when server closes a connection then it becomes stale? How can reading from a connection detect this situation? If not read timeout that what signals it?
>
> Nikita
>
The main limitation of the classic i/o is that network sockets can react
to events only when blocked in an i/o operation. Persistent connections
while kept idle in the connection pool can become half-closed or reset
by the opposite endpoint without the local endpoint realizing it. The
only way to find out whether or not the connection is still valid is by
performing an i/o operation on it. This is percisely what the stale
connection check is about. It is a very short read operation (~ 1 ms)
that either times out if that the socket is still valid, returns
immediately with -1 if the socket has been half-closed or causes a
socket exception if the socket has been reset.
Hope this helps
Oleg
>> On 2. Aug 2021, at 20:27, Oleg Kalnichevski <ol...@apache.org> wrote:
>>
>> [ External sender. Exercise caution. ]
>>
>> On Mon, 2021-08-02 at 15:52 +0300, Nikita Salnikov-Tarnovski wrote:
>>> Thank you for you reply. I have debug some more and unfortunately
>>> have to disagree with you. I currently observer the following:
>>>
>>
>> You are very welcome to disagree with me but it is not going to change
>> the way HttpClient validates persistent connections.
>>
>>
>>> At some point during application run this line throws a
>>> "java.net.SocketTimeoutException: Read timed out"
>>> https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81
>>> <https://github.com/apache/httpcomponents-
>>> client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/
>>> main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#
>>> L81>
>>>
>>> This results in "[read] I/O error: Read timed out\” being written to
>>> logs.
>>> That SocketTimeoutException is then propagated to here:
>>> https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364
>>> <https://github.com/apache/httpcomponents-
>>> core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/
>>> java/org/apache/http/impl/BHttpConnectionBase.java#L364>
>>>
>>> after which `isStale` method returns false. Thus we have a
>>> connection, which threw SocketTimeoutException but is not considered
>>> as stale. From your reply to my previous email I assume that this
>>> exception should mean that connection is stale, right?
>>
>>
>> No, it absolutely should not. That basically means the connection was
>> unable to produce any input data within one ms time period but
>> otherwise was perfectly valid.
>>
>> Oleg
>>
>>>
>>> Nikita
>>>
>>>> On 2. Aug 2021, at 12:50, Oleg Kalnichevski <ol...@apache.org>
>>>> wrote:
>>>>
>>>> [ External sender. Exercise caution. ]
>>>>
>>>>
>>>> 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.exec
>>>>> chain.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.DefaultMan
>>>>> agedHttpClientConnection","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.PoolingH
>>>>> ttpClientConnectionManager","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.PoolingH
>>>>> ttpClientConnectionManager","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.PoolingH
>>>>> ttpClientConnectionManager","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.Default
>>>>> ManagedHttpClientConnection","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.Default
>>>>> ManagedHttpClientConnection","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.execchai
>>>>> n.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.exec
>>>>> chain.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.exec
>>>>> chain.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","thr
>>>>> ead":"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.D
>>>>> efaultManagedHttpClientConnection","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.D
>>>>> efaultManagedHttpClientConnection","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.execcha
>>>>> in.MainClientExec","thread":"signalfx-metrics-
>>>>> publisher","level_value"
>>>>
>>>> -----------------------------------------------------------------
>>>> ----
>>>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>>>> For additional commands, e-mail:
>>>> httpclient-users-help@hc.apache.org
>>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Stale connection still leased and used
Posted by Nikita Salnikov-Tarnovski <ns...@splunk.com.INVALID>.
I am sorry if my response seemed rude. That was not my intention.
I am now confused what does it mean for a connection to be stale? Am I correct in thinking that when server closes a connection then it becomes stale? How can reading from a connection detect this situation? If not read timeout that what signals it?
Nikita
> On 2. Aug 2021, at 20:27, Oleg Kalnichevski <ol...@apache.org> wrote:
>
> [ External sender. Exercise caution. ]
>
> On Mon, 2021-08-02 at 15:52 +0300, Nikita Salnikov-Tarnovski wrote:
>> Thank you for you reply. I have debug some more and unfortunately
>> have to disagree with you. I currently observer the following:
>>
>
> You are very welcome to disagree with me but it is not going to change
> the way HttpClient validates persistent connections.
>
>
>> At some point during application run this line throws a
>> "java.net.SocketTimeoutException: Read timed out"
>> https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81
>> <https://github.com/apache/httpcomponents-
>> client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/
>> main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#
>> L81>
>>
>> This results in "[read] I/O error: Read timed out\” being written to
>> logs.
>> That SocketTimeoutException is then propagated to here:
>> https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364
>> <https://github.com/apache/httpcomponents-
>> core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/
>> java/org/apache/http/impl/BHttpConnectionBase.java#L364>
>>
>> after which `isStale` method returns false. Thus we have a
>> connection, which threw SocketTimeoutException but is not considered
>> as stale. From your reply to my previous email I assume that this
>> exception should mean that connection is stale, right?
>
>
> No, it absolutely should not. That basically means the connection was
> unable to produce any input data within one ms time period but
> otherwise was perfectly valid.
>
> Oleg
>
>>
>> Nikita
>>
>>> On 2. Aug 2021, at 12:50, Oleg Kalnichevski <ol...@apache.org>
>>> wrote:
>>>
>>> [ External sender. Exercise caution. ]
>>>
>>>
>>> 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.exec
>>>> chain.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.DefaultMan
>>>> agedHttpClientConnection","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.PoolingH
>>>> ttpClientConnectionManager","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.PoolingH
>>>> ttpClientConnectionManager","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.PoolingH
>>>> ttpClientConnectionManager","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.Default
>>>> ManagedHttpClientConnection","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.Default
>>>> ManagedHttpClientConnection","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.execchai
>>>> n.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.exec
>>>> chain.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.exec
>>>> chain.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","thr
>>>> ead":"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.D
>>>> efaultManagedHttpClientConnection","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.D
>>>> efaultManagedHttpClientConnection","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.execcha
>>>> in.MainClientExec","thread":"signalfx-metrics-
>>>> publisher","level_value"
>>>
>>> -----------------------------------------------------------------
>>> ----
>>> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
>>> For additional commands, e-mail:
>>> httpclient-users-help@hc.apache.org
>>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Stale connection still leased and used
Posted by Oleg Kalnichevski <ol...@apache.org>.
On Mon, 2021-08-02 at 15:52 +0300, Nikita Salnikov-Tarnovski wrote:
> Thank you for you reply. I have debug some more and unfortunately
> have to disagree with you. I currently observer the following:
>
You are very welcome to disagree with me but it is not going to change
the way HttpClient validates persistent connections.
> At some point during application run this line throws a
> "java.net.SocketTimeoutException: Read timed out"
> https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81
> <https://github.com/apache/httpcomponents-
> client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/
> main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#
> L81>
>
> This results in "[read] I/O error: Read timed out\” being written to
> logs.
> That SocketTimeoutException is then propagated to here:
> https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364
> <https://github.com/apache/httpcomponents-
> core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/
> java/org/apache/http/impl/BHttpConnectionBase.java#L364>
>
> after which `isStale` method returns false. Thus we have a
> connection, which threw SocketTimeoutException but is not considered
> as stale. From your reply to my previous email I assume that this
> exception should mean that connection is stale, right?
No, it absolutely should not. That basically means the connection was
unable to produce any input data within one ms time period but
otherwise was perfectly valid.
Oleg
>
> Nikita
>
> > On 2. Aug 2021, at 12:50, Oleg Kalnichevski <ol...@apache.org>
> > wrote:
> >
> > [ External sender. Exercise caution. ]
> >
> >
> > 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.exec
> > > chain.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.DefaultMan
> > > agedHttpClientConnection","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.PoolingH
> > > ttpClientConnectionManager","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.PoolingH
> > > ttpClientConnectionManager","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.PoolingH
> > > ttpClientConnectionManager","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.Default
> > > ManagedHttpClientConnection","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.Default
> > > ManagedHttpClientConnection","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.execchai
> > > n.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.exec
> > > chain.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.exec
> > > chain.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","thr
> > > ead":"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.D
> > > efaultManagedHttpClientConnection","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.D
> > > efaultManagedHttpClientConnection","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.execcha
> > > in.MainClientExec","thread":"signalfx-metrics-
> > > publisher","level_value"
> >
> > -----------------------------------------------------------------
> > ----
> > To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
> > For additional commands, e-mail:
> > httpclient-users-help@hc.apache.org
> >
---------------------------------------------------------------------
To unsubscribe, e-mail: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org
Re: Stale connection still leased and used
Posted by Nikita Salnikov-Tarnovski <ns...@splunk.com.INVALID>.
Thank you for you reply. I have debug some more and unfortunately have to disagree with you. I currently observer the following:
At some point during application run this line throws a "java.net.SocketTimeoutException: Read timed out"
https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81 <https://github.com/apache/httpcomponents-client/blob/29ba623ebeec67cd6e8d940b2fed9151c16e4daa/httpclient5/src/main/java/org/apache/hc/client5/http/impl/io/LoggingInputStream.java#L81>
This results in "[read] I/O error: Read timed out\” being written to logs.
That SocketTimeoutException is then propagated to here:
https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364 <https://github.com/apache/httpcomponents-core/blob/1f51a73277bda05839ed8b1ccd6fa97db954be35/httpcore/src/main/java/org/apache/http/impl/BHttpConnectionBase.java#L364>
after which `isStale` method returns false. Thus we have a connection, which threw SocketTimeoutException but is not considered as stale. From your reply to my previous email I assume that this exception should mean that connection is stale, right?
Nikita
> On 2. Aug 2021, at 12:50, Oleg Kalnichevski <ol...@apache.org> wrote:
>
> [ External sender. Exercise caution. ]
>
>
> 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-unsubscribe@hc.apache.org
> For additional commands, e-mail: httpclient-users-help@hc.apache.org
>
Re: Stale connection still leased and used
Posted by Oleg Kalnichevski <ol...@apache.org>.
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-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org