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

Receive message connection from ServiceBusProcessorClient closes due to inactivity in service bus #40805

Open
neeraj-metallic opened this issue Jun 25, 2024 · 2 comments
Open

Receive message connection from ServiceBusProcessorClient closes due to inactivity in service bus #40805

neeraj-metallic opened this issue Jun 25, 2024 · 2 comments
Assignees
@anuchandy
Labels
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

@neeraj-metallic
Copy link

Describe the bug
The connection to receive messages from ServiceBusProcessorClient is closed due to inactivity in service bus and it was not able to recreate the connection.

Exception or Stack Trace

2024-06-25 13:04:04.282  INFO 14432 --- [     parallel-4] c.a.c.a.i.ActiveClientTokenManager       : {"az.sdk.message":"Refreshing token.","scopes":"amqp://testsb.servicebus.windows.net/test_queue"}
2024-06-25 13:22:03.541  INFO 14432 --- [     parallel-7] c.a.c.a.i.ActiveClientTokenManager       : {"az.sdk.message":"Refreshing token.","scopes":"amqp://testsb.servicebus.windows.net/test_queue"}
2024-06-25 13:40:02.797  INFO 14432 --- [    parallel-10] c.a.c.a.i.ActiveClientTokenManager       : {"az.sdk.message":"Refreshing token.","scopes":"amqp://testsb.servicebus.windows.net/test_queue"}
2024-06-25 14:02:47.478  WARN 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onTransportError","connectionId":"MF_8cd57c_1719236086768","errorCondition":"amqp:connection:framing-error","errorDescription":"connection aborted","hostName":"testsb.servicebus.windows.net"}
2024-06-25 14:02:47.584  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Disposing of ReactorConnection.","connectionId":"MF_8cd57c_1719236086768","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"connection aborted, errorContext[NAMESPACE: testsb.servicebus.windows.net. ERROR CONTEXT: N/A]"}
2024-06-25 14:02:47.696  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionUnbound","connectionId":"MF_8cd57c_1719236086768","hostName":"testsb.servicebus.windows.net","state":"CLOSED","remoteState":"ACTIVE"}
2024-06-25 14:02:47.700  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ReceiveLinkHandler2    : {"az.sdk.message":"onLinkFinal","connectionId":"MF_8cd57c_1719236086768","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue"}
2024-06-25 14:02:47.704  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.SessionHandler         : {"az.sdk.message":"onSessionFinal.","connectionId":"MF_8cd57c_1719236086768","sessionName":"test_queue"}
2024-06-25 14:02:47.705  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.SendLinkHandler        : {"az.sdk.message":"onLinkFinal","connectionId":"MF_8cd57c_1719236086768","linkName":"cbs:sender","entityPath":"$cbs"}
2024-06-25 14:02:47.705  WARN 14432 --- [ receiverPump-1] c.a.c.amqp.implementation.MessageFlux    : {"az.sdk.message":"Receiver emitted terminal completion.","messageFlux":"mf_eb0a16_1719236086755","connectionId":"MF_8cd57c_1719236086768","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue"}
2024-06-25 14:02:47.705  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ReceiveLinkHandler2    : {"az.sdk.message":"onLinkFinal","connectionId":"MF_8cd57c_1719236086768","linkName":"cbs:receiver","entityPath":"$cbs"}
2024-06-25 14:02:47.707  WARN 14432 --- [ receiverPump-1] c.a.c.amqp.implementation.MessageFlux    : {"az.sdk.message":"Current mediator reached terminal completion-state (retriable:true).","messageFlux":"mf_eb0a16_1719236086755","connectionId":"MF_8cd57c_1719236086768","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue","retryAfter":1000}
2024-06-25 14:02:47.709  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Channel is closed. Requesting upstream.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs"}
2024-06-25 14:02:47.710  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Connection not requested, yet. Requesting one.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs"}
2024-06-25 14:02:47.717  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs","linkName":"cbs"}
2024-06-25 14:02:47.717  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs"}
2024-06-25 14:02:47.718  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Upstream connection publisher was completed. Terminating processor.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs"}
2024-06-25 14:02:47.723  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.SessionHandler         : {"az.sdk.message":"onSessionFinal.","connectionId":"MF_8cd57c_1719236086768","sessionName":"cbs-session"}
2024-06-25 14:02:47.724  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionFinal","connectionId":"MF_8cd57c_1719236086768","errorCondition":"amqp:resource-limit-exceeded","errorDescription":"local-idle-timeout expired","hostName":"testsb.servicebus.windows.net"}
2024-06-25 14:02:47.728  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Closing executor.","connectionId":"MF_8cd57c_1719236086768"}
2024-06-25 14:02:47.730  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.SendLinkHandler        : {"az.sdk.message":"Sender link was never active. Closing endpoint states.","connectionId":"MF_8cd57c_1719236086768","linkName":"cbs","entityPath":"$cbs"}
2024-06-25 14:02:47.730  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ReceiveLinkHandler2    : {"az.sdk.message":"Receiver link was never active. Closing endpoint states","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs","linkName":"cbs"}
2024-06-25 14:02:47.731  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Channel is disposed.","connectionId":"MF_8cd57c_1719236086768","entityPath":"$cbs"}
2024-06-25 14:02:47.731  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onTransportClosed","connectionId":"MF_8cd57c_1719236086768","errorCondition":"amqp:connection:framing-error","errorDescription":"connection aborted","hostName":"testsb.servicebus.windows.net"}
2024-06-25 14:02:47.731  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.handler.GlobalIOHandler        : {"az.sdk.message":"onTransportClosed","connectionId":"MF_8cd57c_1719236086768","hostName":"testsb.servicebus.windows.net"}
2024-06-25 14:02:48.722  WARN 14432 --- [     parallel-3] c.a.c.amqp.implementation.MessageFlux    : {"az.sdk.message":"Requesting a new mediator.","messageFlux":"mf_eb0a16_1719236086755","connectionId":"MF_8cd57c_1719236086768","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue"}
2024-06-25 14:02:48.724  INFO 14432 --- [     parallel-3] c.a.c.a.i.ReactorConnectionCache         : {"az.sdk.message":"The connection is closed, requesting a new connection.","entityPath":"N/A","connectionId":"MF_8cd57c_1719236086768"}
2024-06-25 14:02:48.727  INFO 14432 --- [     parallel-3] c.a.c.a.i.ReactorConnectionCache         : {"az.sdk.message":"Waiting to connect and become active.","entityPath":"N/A","connectionId":"MF_cce23d_1719304368725"}
2024-06-25 14:02:48.727  INFO 14432 --- [     parallel-3] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Creating and starting connection.","connectionId":"MF_cce23d_1719304368725","hostName":"testsb.servicebus.windows.net","port":5671}
2024-06-25 14:02:48.743  INFO 14432 --- [     parallel-3] c.a.c.a.implementation.ReactorExecutor   : {"az.sdk.message":"Starting reactor.","connectionId":"MF_cce23d_1719304368725"}
2024-06-25 14:02:48.747  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionInit","connectionId":"MF_cce23d_1719304368725","hostName":"testsb.servicebus.windows.net","namespace":"testsb.servicebus.windows.net"}
2024-06-25 14:02:48.748  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ReactorHandler         : {"az.sdk.message":"reactor.onReactorInit","connectionId":"MF_cce23d_1719304368725"}
2024-06-25 14:02:48.748  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionLocalOpen","connectionId":"MF_cce23d_1719304368725","hostName":"testsb.servicebus.windows.net"}
2024-06-25 14:02:48.757  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionBound","connectionId":"MF_cce23d_1719304368725","hostName":"testsb.servicebus.windows.net","peerDetails":"testsb.servicebus.windows.net:5671"}
2024-06-25 14:02:50.461  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ConnectionHandler      : {"az.sdk.message":"onConnectionRemoteOpen","connectionId":"MF_cce23d_1719304368725","hostName":"testsb.servicebus.windows.net","remoteContainer":"0befeb3509974c5f9b20ee34e06fedd6_G5"}
2024-06-25 14:02:50.462  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.ReactorConnectionCache         : {"az.sdk.message":"Emitting the new active connection.","entityPath":"N/A","connectionId":"MF_cce23d_1719304368725"}
2024-06-25 14:02:50.713  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.SessionHandler         : {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_cce23d_1719304368725","sessionName":"test_queue","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2024-06-25 14:02:50.715  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Setting CBS channel.","connectionId":"MF_cce23d_1719304368725"}
2024-06-25 14:02:50.957  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.SessionHandler         : {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_cce23d_1719304368725","sessionName":"cbs-session","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2024-06-25 14:02:50.958  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_cce23d_1719304368725","entityPath":"$cbs","linkName":"cbs"}
2024-06-25 14:02:50.958  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_cce23d_1719304368725","entityPath":"$cbs"}
2024-06-25 14:02:50.959  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Next AMQP channel received.","connectionId":"MF_cce23d_1719304368725","entityPath":"$cbs","subscriberId":"un_56124c_1719304370717"}
2024-06-25 14:02:51.479  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.SendLinkHandler        : {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_cce23d_1719304368725","linkName":"cbs:sender","entityPath":"$cbs","remoteTarget":"Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}"}
2024-06-25 14:02:51.480  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.AmqpChannelProcessor           : {"az.sdk.message":"Channel is now active.","connectionId":"MF_cce23d_1719304368725","entityPath":"$cbs"}
2024-06-25 14:02:51.480  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.handler.ReceiveLinkHandler2    : {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_cce23d_1719304368725","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}"}
2024-06-25 14:02:51.722  INFO 14432 --- [ctor-executor-2] c.a.c.a.i.ActiveClientTokenManager       : {"az.sdk.message":"Scheduling refresh token task.","scopes":"amqp://testsb.servicebus.windows.net/test_queue"}
2024-06-25 14:02:51.724  INFO 14432 --- [ctor-executor-2] c.a.c.a.implementation.ReactorSession    : {"az.sdk.message":"Creating a new receiver link.","connectionId":"MF_cce23d_1719304368725","sessionName":"test_queue","linkName":"test_queue_8fb2d1_1719236086750"}
2024-06-25 14:02:51.725  WARN 14432 --- [ctor-executor-2] c.a.c.amqp.implementation.MessageFlux    : {"az.sdk.message":"Setting next mediator and waiting for activation.","messageFlux":"mf_eb0a16_1719236086755","connectionId":"MF_cce23d_1719304368725","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue"}
2024-06-25 14:02:51.726  INFO 14432 --- [ctor-executor-2] c.a.c.a.implementation.ReactorSession    : {"az.sdk.message":"Returning existing receive link.","connectionId":"MF_cce23d_1719304368725","linkName":"test_queue_8fb2d1_1719236086750","entityPath":"test_queue"}
2024-06-25 14:02:51.730  INFO 14432 --- [ctor-executor-1] c.a.c.a.implementation.ReactorExecutor   : {"az.sdk.message":"Processing all pending tasks and closing old reactor.","connectionId":"MF_8cd57c_1719236086768"}
2024-06-25 14:02:51.732  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorDispatcher              : {"az.sdk.message":"Reactor selectable is being disposed.","connectionId":"MF_8cd57c_1719236086768"}
2024-06-25 14:02:51.732  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_8cd57c_1719236086768","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"connectionId[MF_8cd57c_1719236086768] Reactor selectable is disposed.","namespace":"testsb.servicebus.windows.net"}
2024-06-25 14:02:51.751  WARN 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"Error occurred while processing connection state.","exception":"connection aborted, errorContext[NAMESPACE: testsb.servicebus.windows.net. ERROR CONTEXT: N/A]","connectionId":"MF_8cd57c_1719236086768"}
2024-06-25 14:02:51.752  INFO 14432 --- [ctor-executor-1] c.a.c.a.i.ReactorConnection              : {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_8cd57c_1719236086768","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"Finished processing pending tasks.","namespace":"testsb.servicebus.windows.net"}

To Reproduce
Steps to reproduce the behavior:

  • Use ServiceBusProcessorClient to connect to service bus queue
  • observe that after few hours (not fixed) of inactivity the connection closes and it wasn't able to recreate.

Code Snippet

public void receiveMessages() {
        processorClient = new ServiceBusClientBuilder()
                .connectionString(connectString)
                .processor()
                .queueName(queueName)
                .receiveMode(ServiceBusReceiveMode.PEEK_LOCK)
                .disableAutoComplete()
                .processMessage(TestMessageListener::processMessage)
                .processError(context -> processError(context))
                .buildProcessorClient();

        logger.info("Starting message processor");
        processorClient.start();
    }

Expected behavior

  • connection should be recreated on error or close

Setup (please complete the following information):

  • running on AKS
  • Library/Libraries: com.azure:azure-messaging-servicebus:7.17.0
  • Java version: 14
  • App Server/Environment: Tomcat
  • Frameworks: Spring Boot

Application is written in Java and is running in Azure Kubernetes
Service Bus is in Azure
@github-actions github-actions bot added customer-reported Issues that are reported by GitHub users external to the Azure organization. needs-triage This is a new issue that needs to be triaged to the appropriate team. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that labels Jun 25, 2024
@github-actions github-actions bot removed the needs-triage This is a new issue that needs to be triaged to the appropriate team. label Jun 27, 2024
@joshfree
Copy link
Member

@anuchandy could you please take a look?

@anuchandy
Copy link
Member

In the log I see that indeed the TCP connection recovered, re-established a new link to the queue entity (with name test_queue_*). Is there any chance that the app logic in the processor handler stuck? no message will be delivered on the new link until the handler resume

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

@anuchandy anuchandy

Labels
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 @anuchandy @neeraj-metallic