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