Description

karthik-119

opened on Sep 11, 2023

Issue body actions

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

Activity

1. karthik-119 commented on Sep 20, 2023

   

   karthik-119

   on Sep 20, 2023

   Author

   More actions

   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
2. karthik-119 commented on Sep 21, 2023

   

   karthik-119

   on Sep 21, 2023

   Author

   More actions

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

Issue actions