Requests are not processed and can see them stuck in requestQueue

karthik-119 commented 1 year ago

version: 6.5.0

Hi team,

We're experiencing intermittent issue with requests processing where the requests are stuck in queue but not processed. I'll try to explain in detail about the situation and my understanding about Scribe Java lib:

Whenever requests are made using scribe java, there won't be any response back to the client and the requests stuck there for hours until restart of jvm is performed.

Scribejava has ApacheHttpClient that does actual requests to target server. This underlying httpclient has queue mechanism for processing the requests where the requests are added into a queue and processed in async manner.

java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000b150e370> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at com.github.scribejava.httpclient.apache.OAuthAsyncCompletionHandler.getResult(OAuthAsyncCompletionHandler.java:91)
at com.github.scribejava.httpclient.apache.ApacheHttpFuture.get(ApacheHttpFuture.java:37)
at com.github.scribejava.core.httpclient.AbstractAsyncOnlyHttpClient.execute(AbstractAsyncOnlyHttpClient.java:35)
at com.github.scribejava.core.oauth.OAuthService.execute(OAuthService.java:105)

Looking at stacktrace from our thread dump, thread is waiting for the response from this client and we were under assumption that is could be connect timeout issues, this is what we're focusing on from last few weeks.
Therefore, we added connection timeout setting for all calls.
I can see that issue is reproducing even after applying connect timeout setting for client object. There is something else that is causing the issue for which I started analyzing heap dump for.

Heap dump analysis:

From the heap dump, I can see that there are requests stuck in requestQueue but not picked up by ioReactor thread.
InternalHttpAsyncClient 'status' is STOPPED.
IOReactor 'status' is ACTIVE
IOReactor execute() looks like stuck or terminated when creating dispatcher threads.

I tried to understand the flow of execution, and if I understood it correctly somehow the execute() method from AbstractMultiworkerIOReactor got terminated at marked section below:

I would like to request you to look at this issue and help me figuring out what's causing the behavior, is it a bug in code or due to performance reasons? I know it is bit older version but upgrading to latest version can fix the issue? It is not easily reproducible and happens randomly without any pattern.

Note that heap dump is collected after 2 hrs of the issue is reproduced.

Appreciate your help!

Thanks & Regards, Karthik

karthik-119 commented 1 year ago

We've some logging and error trace now, hopefully this can help you analyze and fix the issue:

DEBUG 2023-09-18 10:16:38,706Z [parallel_; tid=11876601] [ o.a.http.impl.nio.client.MainClientExec] : [exchange: 47975] start execution
DEBUG 2023-09-18 10:16:38,706Z [parallel_; tid=11876601] [ o.a.h.client.protocol.RequestAddCookies] : CookieSpec selected: standard
DEBUG 2023-09-18 10:16:38,706Z [parallel_; tid=11876601] [  o.a.h.client.protocol.RequestAuthCache] : Auth cache not set in the context
DEBUG 2023-09-18 10:16:38,706Z [parallel_; tid=11876601] [o.a.h.i.n.client.InternalHttpAsyncClient] : [exchange: 47975] Request connection for {s}->  xxxxxxxxxxxxxxxxxxxxx
DEBUG 2023-09-18 10:16:38,706Z [parallel_; tid=11876601] [.n.c.PoolingNHttpClientConnectionManager] : Connection request: [route: {s}->xxxxxxxxxxxxxxxxxxxxxxxxx][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
ERROR 2023-09-18 10:16:38,757Z [    pool-48041-thread-1] [o.a.h.i.n.client.InternalHttpAsyncClient] : I/O reactor terminated abnormally
org.apache.http.nio.reactor.IOReactorException: Failure opening selector
    at org.apache.http.impl.nio.reactor.AbstractIOReactor.<init>(AbstractIOReactor.java:103)
    at org.apache.http.impl.nio.reactor.BaseIOReactor.<init>(BaseIOReactor.java:85)
    at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:318)
    at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:221)
    at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
    at java.lang.Thread.run(Thread.java:750)
Caused by: java.io.IOException: Unable to establish loopback connection
    at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:94)
    at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:61)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.nio.ch.PipeImpl.<init>(PipeImpl.java:171)
    at sun.nio.ch.SelectorProviderImpl.openPipe(SelectorProviderImpl.java:50)
    at java.nio.channels.Pipe.open(Pipe.java:155)
    at sun.nio.ch.WindowsSelectorImpl.<init>(WindowsSelectorImpl.java:142)
    at sun.nio.ch.WindowsSelectorProvider.openSelector(WindowsSelectorProvider.java:44)
    at java.nio.channels.Selector.open(Selector.java:227)
    at org.apache.http.impl.nio.reactor.AbstractIOReactor.<init>(AbstractIOReactor.java:101)
    ... 5 common frames omitted
Caused by: java.net.SocketException: Socket operation on nonsocket: bind
    at sun.nio.ch.Net.bind0(Native Method)
    at sun.nio.ch.Net.bind(Net.java:461)
    at sun.nio.ch.Net.bind(Net.java:453)
    at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:222)
    at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:85)
    at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:78)
    at sun.nio.ch.PipeImpl$Initializer$LoopbackConnector.run(PipeImpl.java:121)
    at sun.nio.ch.PipeImpl$Initializer.run(PipeImpl.java:76)
    ... 14 common frames omitted

Can you please let me know, what is causing the issue? Is fix needed from scribe java/apache http client? This kind of issues are annoying as they happen intermittently with no pattern and always requires monitoring and manual actions to recover from the situation.

Thanks in Advance

karthik-119 commented 1 year ago

FYI, I've created post in apache forum as well: https://www.apachelounge.com/viewtopic.php?p=42222#42222

scribejava / scribejava

Requests are not processed and can see them stuck in requestQueue #1065