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