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
