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-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
