Re: Stale connection still leased and used

Mon, 02 Aug 2021 14:17:45 -0700 



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-unsubscr...@hc.apache.org
For additional commands, e-mail:
httpclient-users-h...@hc.apache.org




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




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



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























					Reply via email to