Hi Oleg,
The error message is misleading (See below). It looks like Actual error is
because it is unable to acquire lock (From the exception provided earlier
Line 27 of StrictConnPool.java
<https://github.com/apache/httpcomponents-core/blob/rel/v5.2.2/httpcore5/src/main/java/org/apache/hc/core5/pool/StrictConnPool.java>).
Timeout of 0 means don't wait as per java docs of ReentrantLock
<https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/locks/ReentrantLock.html#tryLock-long-java.util.concurrent.TimeUnit->.
So in my case it looks like already one thread acquired lock and another
thread now trying to acquire lock and as TimeOut value is 0, that thread is
returning back and causing that exception to be thrown. As per HTTPClient
java docs
<https://hc.apache.org/httpcomponents-client-5.2.x/current/httpclient5/apidocs/org/apache/hc/client5/http/config/RequestConfig.Builder.html#setConnectionRequestTimeout-org.apache.hc.core5.util.Timeout->
a timeout of 0 to setConnectionRequestTimeout means infinite timeout.
Snippet from *ReentrantLock* java docs
[image: image.png]
Snippet from *RequestConfig.Builder* java docs
[image: image.png]
*Below code produces the same output as observed from HTTPClient logs
provided earlier*
Timeout requestTimeout = Timeout.ZERO_MILLISECONDS;
final Deadline deadline = Deadline.calculate(requestTimeout);
System.out.println(DeadlineTimeoutException.from(deadline));
*Output*
org.apache.hc.core5.util.DeadlineTimeoutException: Deadline:
+292278994-08-17T07:12:55.807+0000, 9223370348824198963 MILLISECONDS overdue
On Wed, Jun 28, 2023 at 1:23 PM sreenivas somavarapu <
soma.sreeni...@gmail.com> wrote:
> Thank you for the help Oleg. I doubt if it has anything to do with system
> clock. If system clock is the problem then it should happen for every
> request, but here it is happening randomly (25 requests out of some 2 lakh
> odd requests) which makes me believe some race condition within code
> (either our code or httpclient code) which might be causing the issue.
> Anyhow I will also look into system aspects side and analyze few other
> scenarios.
>
> Regards,
> Sreenivas
>
> On Wed, Jun 28, 2023, 1:03 PM Oleg Kalnichevski <ol...@apache.org> wrote:
>
>> On Wed, 2023-06-28 at 05:03 +0530, sreenivas somavarapu wrote:
>> > Not sure which timeout you are asking for, I think you might be
>> > asking for
>> > Connection Request Timeout. We set a timeout of 0 MilliSeconds to the
>> > setConnectionRequestTimeout API of the RequestConfig class. Below are
>> > some
>> > other timeouts we set as conveyed earlier
>> > *Note*: Within minute of our tests starts we are seeing these errors
>> >
>> > *Socket Timeout : 180000 ms*
>> >
>> > *Connect Timeout : 180000 ms*
>> > *evictIdleConnections Time: 60000 ms*
>> > *Max per Route : 20*
>> > *Pool Size : 420*
>> >
>>
>>
>> If you look at the log snippet I posted earlier, you will see there is
>> no resource problem. The connection pool is basically empty and there
>> should be no problem acquiring a connection lease.
>>
>> ---
>> ex-0000000002 endpoint lease request (0 MILLISECONDS) [route:
>> {}->http://aghwmw8be2ad6:80][total available: 0; route allocated: 0 of
>> 20; total allocated: 0 of 420]
>> ---
>>
>> The problem is not the resource availability but the crazy deadline
>> value calculated for the lease request.
>>
>> ---
>> ex-0000000002 request failed: Deadline:
>> +292278994-08-17T07:12:55.807+0000, 9223370348978091716 MILLISECONDS overdue
>> ---
>>
>> The deadline is calculated based on two values: the current system time
>> plus timeout. The timeout appears to be zero. See the first log entry.
>> The only plausible explanation is that your system clock is completely
>> off.
>>
>> This is all I can do for you.
>>
>> Oleg
>>
>>
>>
>> > Below is the code we use to initialize HTTPClient and Pooling
>> > Connection
>> > Manager
>> >
>> > PoolingAsyncClientConnectionManager connectionManager =
>> > PoolingAsyncClientConnectionManagerBuilder.create()
>> > .setMaxConnTotal(420)
>> > .setMaxConnPerRoute(20)
>> > .setDefaultConnectionConfig(ConnectionConfig.custom()
>> >
>> > .setValidateAfterInactivity(TimeValue.ofSeconds(-1))
>> > .setSocketTimeout(180000,
>> > TimeUnit.MILLISECONDS)
>> > .setConnectTimeout(180000,
>> > TimeUnit.MILLISECONDS)
>> > .setTimeToLive(TimeValue.ofMinutes(3))
>> > .build())
>> > .build();
>> >
>> > connectionManager.setDefaultMaxPerRoute(20);
>> >
>> > H2Config h2 =
>> > H2Config.custom().setPushEnabled(false).build();
>> > final IOReactorConfig ioReactorConfig =
>> > IOReactorConfig.custom()
>> > .setSoTimeout(18000, TimeUnit.MILLISECONDS)
>> > .setSoLinger(TimeValue.ofMilliseconds(-1))
>> > .setSoReuseAddress(false)
>> > .setTcpNoDelay(true)
>> > .setRcvBufSize(8192)
>> > .setSndBufSize(8192)
>> > .setSoKeepAlive(true)
>> > .build();
>> >
>> > final HttpAsyncClientBuilder hacBuilder =
>> > HttpAsyncClientBuilder.create()
>> > .setConnectionManager(connectionManager)
>> > .setIOReactorConfig(ioReactorConfig)
>> > .setH2Config(h2)
>> > .setDefaultRequestConfig(RequestConfig.custom()
>> > .setConnectionRequestTimeout(0,
>> > TimeUnit.MILLISECONDS)
>> > .setExpectContinueEnabled(false)
>> >
>> > .setResponseTimeout(Timeout.ofMilliseconds(5000))
>> > .setCookieSpec(StandardCookieSpec.RELAXED)
>> > .setDefaultKeepAlive(3, TimeUnit.MINUTES)
>> >
>> > .setConnectionKeepAlive(TimeValue.ofMinutes(3))
>> > .setAuthenticationEnabled(false)
>> > .build())
>> > .setUserAgent("HTTPTest/1.0")
>> >
>> > .setConnectionReuseStrategy(DefaultConnectionReuseStrategy.INSTANCE)
>> >
>> > .setKeepAliveStrategy(DefaultConnectionKeepAliveStrategy.INSTANCE)
>> > .setRetryStrategy(new
>> > DefaultHttpRequestRetryStrategy(3,
>> > TimeValue.ofMilliseconds(100)))
>> > .disableRedirectHandling()
>> > .disableAuthCaching()
>> > .evictExpiredConnections()
>> >
>> > .evictIdleConnections(TimeValue.ofMilliseconds(60000));
>> >
>> > httpClient = hacBuilder.build();
>> > httpClient.start();
>> >
>> >
>> > On Tue, Jun 27, 2023 at 11:21 PM Oleg Kalnichevski <ol...@apache.org>
>> > wrote:
>> >
>> > > On Tue, 2023-06-27 at 21:12 +0530, sreenivas somavarapu wrote:
>> > > > Hi Oleg,
>> > > >
>> > > > Below is trace line from httpclient logs which is logged at
>> > > > DEBUG.
>> > > >
>> > > > 2023-06-27 14:38:04,091 DEBUG
>> > > > [org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnection
>> > > > Mana
>> > > > ger]
>> > > > ex-0000000002 endpoint lease failed
>> > > > 2023-06-27 14:38:04,091 DEBUG
>> > > > [org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncC
>> > > > lien
>> > > > t]
>> > > > ex-0000000002 request failed: Deadline: +292278994-08-
>> > > > 17T07:12:55.807+0000,
>> > > > 9223370348978091716 MILLISECONDS overdue
>> > > >
>> > > > Regards,
>> > > > Sreenivas
>> > > >
>> > >
>> > > Look at the deadline. This makes no sense:
>> > >
>> > > Deadline: +292278994-08-17T07:12:55.807+0000, 9223370348978091716
>> > > MILLISECONDS overdue
>> > >
>> > > What? Year 292278994? What is the timeout value you are using?
>> > >
>> > >
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,060 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncCli
>> > > ent]
>> > > ex-0000000002 preparing request execution
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,076 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-
>> > > 0000000002
>> > > target auth state: UNCHALLENGED
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,076 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.AsyncProtocolExec] ex-
>> > > 0000000002
>> > > proxy auth state: UNCHALLENGED
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,076 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.AsyncConnectExec] ex-
>> > > 0000000002
>> > > acquiring connection with route {}->http://aghwmw8be2ad6:80
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,076 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.InternalHttpAsyncClient]
>> > > ex-0000000002 acquiring endpoint (0 MILLISECONDS)
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,076 DEBUG
>> > > [org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionMa
>> > > nager]
>> > > ex-0000000002 endpoint lease request (0 MILLISECONDS) [route:
>> > > {}->http://aghwmw8be2ad6:80][total available: 0; route allocated: 0
>> > > of
>> > > 20; total allocated: 0 of 420]
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,091 DEBUG
>> > > [org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionMa
>> > > nager]
>> > > ex-0000000002 endpoint lease failed
>> > > httpclient.log.06-27-23.1:2023-06-27 14:38:04,091 DEBUG
>> > > [org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncCli
>> > > ent]
>> > > ex-0000000002 request failed: Deadline: +292278994-08-
>> > > 17T07:12:55.807+0000,
>> > > 9223370348978091716 MILLISECONDS overdue
>> > >
>> > >
>> > >
>> > >
>> > > > On Tue, Jun 27, 2023 at 9:02 PM Oleg Kalnichevski
>> > > > <ol...@apache.org>
>> > > > wrote:
>> > > >
>> > > > > On Tue, 2023-06-27 at 20:50 +0530, sreenivas somavarapu wrote:
>> > > > > > Hi Oleg,
>> > > > > >
>> > > > > > PFA httpclient logs with suggested configuration. Attaching
>> > > > > > only
>> > > > > > 2 of
>> > > > > > httpclient logs which has the DeadlineTimeoutException
>> > > > > > exception
>> > > > > > occuring 6
>> > > > > > times out of total 25 times for a 20 minute run (And these 2
>> > > > > > files
>> > > > > > are
>> > > > > > during start of the test i.e., initial 1 / 2 minutes run
>> > > > > > itself).
>> > > > > >
>> > > > > > Around 61 files of 10 MB each have been generated for a
>> > > > > > complete
>> > > > > > 20
>> > > > > > minutes
>> > > > > > run with below logging configuration. Let me know if you want
>> > > > > > all
>> > > > > > those 62
>> > > > > > files.
>> > > > > >
>> > > > > > logger.httpClient.name = org.apache.hc.client5.http.impl
>> > > > > > logger.httpClient.level = DEBUG
>> > > > > > logger.httpClient.additivity = false
>> > > > > > logger.httpClient.appenderRef.rolling.ref = httpclientRolling
>> > > > > >
>> > > > > > logger.httpCore.name = org.apache.hc.core5
>> > > > > > logger.httpCore.level = INFO
>> > > > > > logger.httpCore.additivity = false
>> > > > > > logger.httpCore.appenderRef.rolling.ref = httpclientRolling
>> > > > > >
>> > > > > >
>> > > > > > httpclienttracelogs.zip
>> > > > > > <
>> > > > > >
>> > >
>> https://drive.google.com/file/d/1WPNCQ0SZanAzZb-bmYf7IhDK-BQS9VNy/view
>> > > > > > ?usp=drive_web>
>> > > > > >
>> > > > > >
>> > > > >
>> > > > > I do not see a single timeout exception or any exception of any
>> > > > > kind in
>> > > > > the logs. What am I supposed to do with these logs?
>> > > > >
>> > > > >
>> > > > > oleg@ok2c:~/src/misc/httpclienttracelogs$ grep -i Timeout *
>> > > > > oleg@ok2c:~/src/misc/httpclienttracelogs$ grep -i exception *
>> > > > > oleg@ok2c:~/src/misc/httpclienttracelogs$
>> > > > >
>> > > > >
>> > > > > Oleg
>> > > > >
>> > > > >
>> > > > > >
>> > > > > > On Mon, Jun 26, 2023 at 9:58 PM Oleg Kalnichevski
>> > > > > > <ol...@apache.org>
>> > > > > > wrote:
>> > > > > >
>> > > > > > > On Mon, 2023-06-26 at 18:20 +0530, sreenivas somavarapu
>> > > > > > > wrote:
>> > > > > > > > Hi Oleg,
>> > > > > > > >
>> > > > > > > >
>> > > > > > > >
>> > > > > > > > Hope you were able to access logs provided and in the
>> > > > > > > > process
>> > > > > > > > of
>> > > > > > > > analyzing
>> > > > > > > > them.
>> > > > > > >
>> > > > > > > No, I was not. The URL was access protected. I requested
>> > > > > > > access
>> > > > > > > but
>> > > > > > > no
>> > > > > > > one reacted. Anyway, it is irrelevant now. Please re-run
>> > > > > > > the
>> > > > > > > whole
>> > > > > > > thing with the logging settings I sent you in my previous
>> > > > > > > message.
>> > > > > > >
>> > > > > > > Oleg
>> > > > > > >
>> > > > > > >
>> > > > > > > -----------------------------------------------------------
>> > > > > > > ----
>> > > > > > > ----
>> > > > > > > --
>> > > > > > > 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
>>
>>
--
Cheers,
S. Sreenivas
