Visitar URL original
Requests are not processed and can see them stuck in requestQueue · Issue #1065 · scribejava/scribejava · GitHub
Skip to content

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

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

Description

@karthik-119
karthik-119
opened on Sep 11, 2023

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.
    Requests-stuck-in-queue
  • InternalHttpAsyncClient 'status' is STOPPED.
    InternalHttpAsyncClient-status-STOPPED
  • IOReactor 'status' is ACTIVE
    IOReactor-status
  • IOReactor execute() looks like stuck or terminated when creating dispatcher threads.
    IOReactor-behavior

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:
image

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
    karthik-119
    on Sep 20, 2023
    Author

    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
    karthik-119
    on Sep 21, 2023
    Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions