Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Consuming messages stuck after specific network issues #21846

Closed
Leshist opened this issue May 26, 2021 · 3 comments
Closed

[BUG] Consuming messages stuck after specific network issues #21846

Leshist opened this issue May 26, 2021 · 3 comments
Assignees
@YijunXieMS
Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus

Comments

@Leshist
Copy link

Leshist commented May 26, 2021

Describe the bug
Consumer gets stuck not consuming messages when specific Network issues occur, we have this issue in production and its gone after restarting the app

To Reproduce

  1. create messages in topic
  2. start consuming them using consumer code snippet provided
  3. cause network break using command prompt terminal snippet

Code Snippet

Consumer code:

ServiceBusClientBuilder builder = new ServiceBusClientBuilder()
        .connectionString(connectionString);

    ServiceBusReceiverAsyncClient receiver = builder
        .receiver()
        .disableAutoComplete()
        .prefetchCount(1)
        .maxAutoLockRenewDuration(Duration.ZERO)
        .topicName("test")
        .subscriptionName("test")
        .buildAsyncClient();

    Disposable subscription = receiver.receiveMessages()
        .flatMap(message -> {
          System.out.printf("Sequence #: %s. Contents: %s%n", message.getSequenceNumber(), message.getBody());
          try {
            Thread.sleep(1_000);
          } catch (InterruptedException e) {
            e.printStackTrace();
          }
          return receiver
              .complete(message)
              .onErrorResume(e -> {
                e.printStackTrace();
                return Mono.empty();
              });
        })
        .doOnError(e -> System.out.println("ERROR: " + e.getMessage()))
        .doOnComplete(() -> System.out.println("DONE"))
        .subscribe();

Command promt(windows terminal) commands to break network:

ipconfig/release
ipconfig/renew

Expected behavior
Messages are picked up properly after connection is restored

Setup (please complete the following information):

  • OS: Windows 10, Version 10.0.19042 Build 19042
  • IDE : IntelliJ
  • 7.0.1

Exception or Stack Trace
here's a bit of consuming with code snippet provided, right before ipconfig/release, and stuck after ipconfig/renew

26-05-2021 11:48:00.985 [reactor-executor-1] DEBUG c.a.c.a.i.handler.ReceiveLinkHandler - onDelivery connectionId[MF_5161e7_1622018873103], entityPath[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164], updatedLinkCredit[0],remoteCredit[0], remoteCondition[Error{condition=null, description='null', info=null}], delivery.isPartial[false]
Sequence #: 2001. Contents: 56-x
26-05-2021 11:48:01.135 [reactor-executor-1] WARN c.a.c.a.i.handler.ConnectionHandler - onTransportError hostname[our-sb-link:5671], connectionId[MF_5161e7_1622018873103], error[An existing connection was forcibly closed by the remote host]
26-05-2021 11:48:01.138 [reactor-executor-1] DEBUG c.a.c.a.i.ReactorConnection - connectionId[MF_5161e7_1622018873103]: State CLOSED
26-05-2021 11:48:01.144 [reactor-executor-1] DEBUG c.a.m.s.i.ServiceBusReactorAmqpConnection - Disposing of connection.
26-05-2021 11:48:01.145 [reactor-executor-1] INFO c.a.c.a.i.ReactorConnection - connectionId[MF_5161e7_1622018873103], errorCondition[n/a]: Disposing of ReactorConnection.
26-05-2021 11:48:01.145 [reactor-executor-1] INFO c.a.c.a.i.ReactorConnection - connectionId[MF_5161e7_1622018873103]: Removing session 'test/subscriptions/test'
26-05-2021 11:48:01.145 [reactor-executor-1] INFO c.a.c.a.i.ReactorSession - connectionId[MF_5161e7_1622018873103], sessionId[test/subscriptions/test], errorCondition[n/a]: Disposing of session.
26-05-2021 11:48:01.147 [reactor-executor-1] DEBUG c.a.c.a.i.ReactorReceiver - connectionId[MF_5161e7_1622018873103], path[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164]: setting error condition null
26-05-2021 11:48:01.148 [reactor-executor-1] INFO c.a.c.a.i.ReactorConnection - connectionId[MF_5161e7_1622018873103]: Removing session 'cbs-session'
26-05-2021 11:48:01.148 [reactor-executor-1] INFO c.a.c.a.i.ReactorSession - connectionId[MF_5161e7_1622018873103], sessionId[cbs-session], errorCondition[n/a]: Disposing of session.
26-05-2021 11:48:01.993 [boundedElastic-2] DEBUG c.a.m.s.ServiceBusReceiverAsyncClient - test/subscriptions/test: Update started. Disposition: COMPLETED. Lock: bb6da97c-13a6-459d-a40d-c6ae2ffa4b4a. SessionId: null.
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkCredits: '0', expectedTotalCredit: '1'
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - prefetch: '1', requested: '2', linkCredits: '0', expectedTotalCredit: '1', queuedMessages:'1', creditsToAdd: '0', messageQueue.size(): '0'
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Link credits='0', Link credits to add: '0'
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkCredits: '0', expectedTotalCredit: '1'
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - prefetch: '1', requested: '2', linkCredits: '0', expectedTotalCredit: '1', queuedMessages:'1', creditsToAdd: '0', messageQueue.size(): '0'
26-05-2021 11:48:01.993 [boundedElastic-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Link credits='0', Link credits to add: '0'
26-05-2021 11:48:53.819 [parallel-2] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.ReactorExecutor - Unable to acquire dispose reactor semaphore within timeout.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.AmqpExceptionHandler - Shutdown received: ReactorExecutor.close() was called., isTransient[false], initiatedByClient[true]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.m.s.i.ServiceBusConnectionProcessor - Attempted 1 times to get a new AMQP connection
26-05-2021 11:49:01.152 [reactor-executor-1] WARN c.a.m.s.i.ServiceBusConnectionProcessor - Retry #1. Transient error occurred. Retrying after 4511 ms.
An existing connection was forcibly closed by the remote host, errorContext[NAMESPACE: our-sb-link]
com.azure.core.amqp.exception.AmqpException: An existing connection was forcibly closed by the remote host, errorContext[NAMESPACE: our-sb-link]
at com.azure.core.amqp.implementation.ExceptionUtil.toException(ExceptionUtil.java:85) ~[azure-core-amqp-2.0.1.jar:na]
at com.azure.core.amqp.implementation.handler.ConnectionHandler.notifyErrorContext(ConnectionHandler.java:306) [azure-core-amqp-2.0.1.jar:na]
at com.azure.core.amqp.implementation.handler.ConnectionHandler.onTransportError(ConnectionHandler.java:209) [azure-core-amqp-2.0.1.jar:na]
at org.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:191) ~[proton-j-0.33.4.jar:na]
at org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108) ~[proton-j-0.33.4.jar:na]
at org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324) ~[proton-j-0.33.4.jar:na]
at org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:291) ~[proton-j-0.33.4.jar:na]
at com.azure.core.amqp.implementation.ReactorExecutor.run(ReactorExecutor.java:82) ~[azure-core-amqp-2.0.1.jar:na]
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_281]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_281]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.handler.SessionHandler - onSessionLocalClose connectionId[test/subscriptions/test], entityName[MF_5161e7_1622018873103], condition[Error{condition=null, description='null', info=null}]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkLocalClose connectionId[MF_5161e7_1622018873103], linkName[test/subscriptions/test_cc59ed_1622018873164], errorCondition[null], errorDescription[null]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.handler.SessionHandler - onSessionLocalClose connectionId[cbs-session], entityName[MF_5161e7_1622018873103], condition[Error{condition=null, description='null', info=null}]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionLocalClose hostname[our-sb-link:5671], connectionId[MF_5161e7_1622018873103], errorCondition[null], errorDescription[null]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionUnbound hostname[our-sb-link:5671], connectionId[MF_5161e7_1622018873103], state[CLOSED], remoteState[ACTIVE]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkFinal connectionId[MF_5161e7_1622018873103], linkName[test/subscriptions/test_cc59ed_1622018873164]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.ReactorReceiver - connectionId[MF_5161e7_1622018873103], path[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164]: State CLOSED
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Receive link endpoint states are closed. Requesting another.
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Requesting a new AmqpReceiveLink from upstream.
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.m.s.ServiceBusReceiverAsyncClient - Created consumer for Service Bus resource: [test/subscriptions/test] mode: [PEEK_LOCK] sessionEnabled? true transferEntityPath: [N/A], entityType: [SUBSCRIPTION]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkName[test/subscriptions/test_cc59ed_1622018873164] entityPath[test/subscriptions/test]. Setting next AMQP receive link.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Receive link endpoint states are closed. Requesting another.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Requesting a new AmqpReceiveLink from upstream.
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkCredits: '0', expectedTotalCredit: '1'
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - prefetch: '1', requested: '1', linkCredits: '0', expectedTotalCredit: '1', queuedMessages:'1', creditsToAdd: '0', messageQueue.size(): '0'
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Link credits='0', Link credits to add: '0'
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.m.s.i.ServiceBusConnectionProcessor - Added a subscriber com.azure.core.amqp.implementation.AmqpChannelProcessor$ChannelSubscriber@308d8cf to AMQP channel processor. Total subscribers = 1
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.SessionHandler - onSessionFinal connectionId[MF_5161e7_1622018873103], entityName[test/subscriptions/test], condition[null], description[null]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_5161e7_1622018873103], sessionName[test/subscriptions/test]: State
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.SendLinkHandler - onLinkFinal connectionId[MF_5161e7_1622018873103], linkName[cbs:sender]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkFinal connectionId[MF_5161e7_1622018873103], linkName[cbs:receiver]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.SessionHandler - onSessionFinal connectionId[MF_5161e7_1622018873103], entityName[cbs-session], condition[null], description[null]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_5161e7_1622018873103], sessionName[cbs-session]: State
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionFinal hostname[our-sb-link:5671], connectionId[MF_5161e7_1622018873103], errorCondition[null], errorDescription[null]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.SendLinkHandler - onLinkLocalClose connectionId[MF_5161e7_1622018873103], linkName[cbs:sender], errorCondition[null], errorDescription[null]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkLocalClose connectionId[MF_5161e7_1622018873103], linkName[cbs:receiver], errorCondition[null], errorDescription[null]
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: null
26-05-2021 11:49:01.152 [reactor-executor-1] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: null
26-05-2021 11:49:01.152 [reactor-executor-1] WARN c.a.c.a.i.ReactorExecutor - connectionId[MF_5161e7_1622018873103], message[Scheduling reactor failed because the scheduler has been shut down.]
Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2fa4d032 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@ffcf7f6[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@2fa4d032 rejected from java.util.concurrent.ScheduledThreadPoolExecutor@ffcf7f6[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:326) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:549) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor.submit(ScheduledThreadPoolExecutor.java:648) ~[na:1.8.0_281]
at java.util.concurrent.Executors$DelegatedExecutorService.submit(Executors.java:681) ~[na:1.8.0_281]
at reactor.core.scheduler.Schedulers.directSchedule(Schedulers.java:1148) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at reactor.core.scheduler.SingleScheduler.schedule(SingleScheduler.java:118) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at com.azure.core.amqp.implementation.ReactorExecutor.run(ReactorExecutor.java:87) ~[azure-core-amqp-2.0.1.jar:na]
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) ~[reactor-core-3.3.12.RELEASE.jar:3.3.12.RELEASE]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_281]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_281]
26-05-2021 11:49:01.152 [reactor-executor-1] INFO c.a.c.a.i.ReactorExecutor - connectionId[MF_5161e7_1622018873103], message[Stopping the reactor because thread was interrupted or the reactor has no more events to process.]
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.m.s.i.ServiceBusConnectionProcessor - Retry #1. Requesting from upstream.
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.m.s.i.ServiceBusConnectionProcessor - namespace[] entityPath[our-sb-link]: Connection not requested, yet. Requesting one.
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.m.s.i.ServiceBusConnectionProcessor - namespace[] entityPath[our-sb-link]: Setting next AMQP channel.
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.m.s.i.ServiceBusConnectionProcessor - namespace[] entityPath[our-sb-link]: Next AMQP channel received, updating 1 current subscribers
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.c.a.i.ReactorConnection - connectionId[MF_7a3cbf_1622018873133]: Creating and starting connection to our-sb-link:5671
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.c.a.i.ReactorExecutor - connectionId[MF_7a3cbf_1622018873133], message[Starting reactor.]
26-05-2021 11:49:05.673 [parallel-3] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_7a3cbf_1622018873133], sessionName[test/subscriptions/test]: State
26-05-2021 11:49:05.673 [parallel-3] DEBUG c.a.m.s.i.ServiceBusReactorAmqpConnection - Get or create consumer for path: 'test/subscriptions/test'
26-05-2021 11:49:05.673 [parallel-3] INFO c.a.c.a.i.AzureTokenManagerProvider - Creating new token manager for audience[amqp://our-sb-link/test/subscriptions/test], resource[test/subscriptions/test]
26-05-2021 11:49:05.673 [parallel-3] DEBUG c.a.c.a.i.ReactorConnection - connectionId[MF_38321f_1622018945673]: State UNINITIALIZED
26-05-2021 11:49:05.673 [reactor-executor-2] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionInit hostname[our-sb-link], connectionId[MF_7a3cbf_1622018873133]
26-05-2021 11:49:05.673 [reactor-executor-2] INFO c.a.c.a.i.handler.ReactorHandler - connectionId[MF_7a3cbf_1622018873133] reactor.onReactorInit
26-05-2021 11:49:05.673 [reactor-executor-2] DEBUG c.a.c.a.i.handler.SessionHandler - onSessionLocalOpen connectionId[MF_7a3cbf_1622018873133], entityName[test/subscriptions/test], condition[Error{condition=null, description='null', info=null}]
26-05-2021 11:49:05.673 [reactor-executor-2] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionLocalOpen hostname[our-sb-link:5671], connectionId[MF_7a3cbf_1622018873133], errorCondition[null], errorDescription[null]
26-05-2021 11:49:05.673 [reactor-executor-2] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionBound hostname[our-sb-link], connectionId[MF_7a3cbf_1622018873133]
26-05-2021 11:49:05.707 [reactor-executor-2] INFO c.a.c.a.i.h.StrictTlsContextSpi - SSLv2Hello was an enabled protocol. Filtering out.
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.handler.ConnectionHandler - onConnectionRemoteOpen hostname[our-sb-link:5671], connectionId[MF_7a3cbf_1622018873133], remoteContainer[38b3d17f30ae420aa4458b2d09d502ba_G53]
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorConnection - connectionId[MF_7a3cbf_1622018873133]: State ACTIVE
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.m.s.i.ServiceBusConnectionProcessor - namespace[] entityPath[our-sb-link]: Channel is now active.
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.handler.SessionHandler - onSessionRemoteOpen connectionId[MF_7a3cbf_1622018873133], entityName[test/subscriptions/test], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_7a3cbf_1622018873133], sessionName[test/subscriptions/test]: State
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.ReactorConnection - Setting CBS channel.
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_7a3cbf_1622018873133], sessionName[cbs-session]: State
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.ReactorConnection - Emitting new response channel. connectionId: MF_7a3cbf_1622018873133. entityPath: $cbs. linkName: cbs.
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.RequestResponseChannel - namespace[MF_7a3cbf_1622018873133] entityPath[$cbs]: Setting next AMQP channel.
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.RequestResponseChannel - namespace[MF_7a3cbf_1622018873133] entityPath[$cbs]: Next AMQP channel received, updating 0 current subscribers
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.handler.SessionHandler - onSessionLocalOpen connectionId[MF_7a3cbf_1622018873133], entityName[cbs-session], condition[Error{condition=null, description='null', info=null}]
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: null
26-05-2021 11:49:05.907 [reactor-executor-2] DEBUG c.a.c.a.i.handler.SendLinkHandler - onLinkLocalOpen connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:sender], localTarget[Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}]
26-05-2021 11:49:05.907 [reactor-executor-2] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkLocalOpen connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:receiver], localSource[Source{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}]
26-05-2021 11:49:05.953 [reactor-executor-2] INFO c.a.c.a.i.handler.SessionHandler - onSessionRemoteOpen connectionId[MF_7a3cbf_1622018873133], entityName[cbs-session], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
26-05-2021 11:49:05.953 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorSession - connectionId[MF_7a3cbf_1622018873133], sessionName[cbs-session]: State
26-05-2021 11:49:05.953 [reactor-executor-2] INFO c.a.c.a.i.handler.SendLinkHandler - onLinkRemoteOpen connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:sender], remoteTarget[Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}]
26-05-2021 11:49:05.953 [reactor-executor-2] INFO c.a.c.a.i.RequestResponseChannel - namespace[MF_7a3cbf_1622018873133] entityPath[$cbs]: Channel is now active.
26-05-2021 11:49:05.953 [reactor-executor-2] DEBUG c.a.c.a.i.handler.SendLinkHandler - onLinkFlow connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:sender], unsettled[0], credit[100]
26-05-2021 11:49:05.953 [reactor-executor-2] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkRemoteOpen connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:receiver], remoteSource[Source{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}]
26-05-2021 11:49:05.953 [reactor-executor-2] INFO c.a.c.a.i.RequestResponseChannel - namespace[MF_7a3cbf_1622018873133] entityPath[$cbs]: Channel is now active.
26-05-2021 11:49:05.953 [reactor-executor-2] DEBUG c.a.c.a.i.RequestResponseChannel - cbs - Scheduling on dispatcher. Message Id 1
26-05-2021 11:49:05.953 [reactor-executor-2] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: null
26-05-2021 11:49:05.953 [reactor-executor-2] DEBUG c.a.c.a.i.handler.SendLinkHandler - onLinkFlow connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:sender], unsettled[0], credit[99]
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.c.a.i.RequestResponseChannel - cbs - Settling message: 1
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.c.a.i.ActiveClientTokenManager - Scheduling refresh token task. scopes[amqp://our-sb-link/test/subscriptions/test]
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.c.a.i.handler.ReceiveLinkHandler - onDelivery connectionId[MF_7a3cbf_1622018873133], entityPath[$cbs], linkName[cbs:receiver], updatedLinkCredit[0],remoteCredit[0], remoteCondition[Error{condition=null, description='null', info=null}], delivery.isPartial[false]
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: null
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.c.a.i.ReactorSession - Creating a new receiver link with linkName test/subscriptions/test_cc59ed_1622018873164
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorReceiver - connectionId[MF_7a3cbf_1622018873133], path[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164]: State UNINITIALIZED
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorReceiver - Token refreshed: ACCEPTED
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.m.s.ServiceBusReceiverAsyncClient - Created consumer for Service Bus resource: [test/subscriptions/test] mode: [PEEK_LOCK] sessionEnabled? true transferEntityPath: [N/A], entityType: [SUBSCRIPTION]
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkName[test/subscriptions/test_cc59ed_1622018873164] entityPath[test/subscriptions/test]. Setting next AMQP receive link.
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - linkCredits: '0', expectedTotalCredit: '1'
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - prefetch: '1', requested: '1', linkCredits: '0', expectedTotalCredit: '1', queuedMessages:'1', creditsToAdd: '0', messageQueue.size(): '0'
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.m.s.i.ServiceBusReceiveLinkProcessor - Link credits='0', Link credits to add: '0'
26-05-2021 11:49:05.985 [reactor-executor-2] DEBUG c.a.m.s.i.ServiceBusReactorAmqpConnection - Get or create consumer for path: 'test/subscriptions/test'
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.c.a.i.ReactorSession - linkName[test/subscriptions/test_cc59ed_1622018873164] entityPath[test/subscriptions/test]: Returning existing receive link.
26-05-2021 11:49:05.985 [reactor-executor-2] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkLocalOpen connectionId[MF_7a3cbf_1622018873133], entityPath[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164], localSource[Source{address='test/subscriptions/test', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}]
26-05-2021 11:49:06.024 [reactor-executor-2] INFO c.a.c.a.i.handler.ReceiveLinkHandler - onLinkRemoteOpen connectionId[MF_7a3cbf_1622018873133], entityPath[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164], remoteSource[Source{address='test/subscriptions/test', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}]
26-05-2021 11:49:06.024 [reactor-executor-2] DEBUG c.a.c.a.i.ReactorReceiver - connectionId[MF_7a3cbf_1622018873133], path[test/subscriptions/test], linkName[test/subscriptions/test_cc59ed_1622018873164]: State ACTIVE
26-05-2021 11:50:05.730 [reactor-executor-2] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: EventImpl{type=TIMER_TASK, context=org.apache.qpid.proton.reactor.impl.TaskImpl@392094fa}
26-05-2021 11:50:05.923 [reactor-executor-2] DEBUG c.a.c.a.i.handler.DispatchHandler - Running task for event: EventImpl{type=TIMER_TASK, context=org.apache.qpid.proton.reactor.impl.TaskImpl@26283ae}
26-05-2021 11:50:06.000 [parallel-3] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
26-05-2021 11:51:06.015 [parallel-3] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
26-05-2021 11:52:06.006 [parallel-3] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
26-05-2021 11:53:06.020 [parallel-3] DEBUG c.a.m.s.i.ServiceBusReactorReceiver - linkName[test/subscriptions/test_cc59ed_1622018873164]: Cleaning timed out update work tasks.
@ghost ghost added needs-triage This is a new issue that needs to be triaged to the appropriate team. customer-reported Issues that are reported by GitHub users external to the Azure organization. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that labels May 26, 2021
@joshfree joshfree added Client This issue points to a problem in the data-plane of the library. Service Bus labels May 26, 2021
@ghost ghost removed the needs-triage This is a new issue that needs to be triaged to the appropriate team. label May 26, 2021
@joshfree
Copy link
Member

@YijunXieMS could you please follow up with @Leshist
/cc @hemanttanwar

@YijunXieMS
Copy link
Contributor

@Leshist Last week we release azure-messaging-servicebus 7.2.2, which fixed some problems with connection retry. Could you try it?

@Leshist
Copy link
Author

Leshist commented Jun 4, 2021

@YijunXieMS this case is no longer reproducible with 7.2.2, we'll upgrade and will see if issue with stuck consumer is gone, Thanks!

@Leshist Leshist closed this as completed Jun 4, 2021
@github-actions github-actions bot locked and limited conversation to collaborators Apr 12, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@YijunXieMS YijunXieMS

Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@joshfree @Leshist @YijunXieMS