Skip to content

[BUG] Failure to send message: 'Cannot send a message when request response channel is disposed' with no retry #34646

New issue
New issue
Closed
Closed
[BUG] Failure to send message: 'Cannot send a message when request response channel is disposed' with no retry#34646
Assignees
anuchandy
Labels
ClientThis issue points to a problem in the data-plane of the library.Service Buscustomer-reportedIssues that are reported by GitHub users external to the Azure organization.needs-team-triageWorkflow: This issue needs the team to triage.questionThe issue doesn't require a change to the product in order to be resolved. Most issues start as that

Description

@AndreasPetersen
Andreas Petersen (AndreasPetersen)
opened on Apr 25, 2023

Describe the bug
We received a Cannot send a message when request response channel is disposed error when trying to send a message. It seems that the message was not retried to be sent, despite the fact that we are using the default retry policy that should retry up to three times.

Exception or Stack Trace
Stacktrace of the error itself:

com.azure.messaging.servicebus.ServiceBusException: Cannot send a message when request response channel is disposed.
	at com.azure.messaging.servicebus.ServiceBusSenderAsyncClient.mapError(ServiceBusSenderAsyncClient.java:822)
	at reactor.core.publisher.Mono.lambda$onErrorMap$31(Mono.java:3776)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onError(MonoFlatMap.java:172)
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onError(MonoPeekTerminal.java:258)
	at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
	at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:225)
	at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:274)
	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:415)
	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:251)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:537)
	at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:343)
	at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:100)
	at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
	at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:190)
	at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
	at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.onError(FluxTimeout.java:219)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onError(FluxPeekFuseable.java:234)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
	at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:278)
	at reactor.core.publisher.MonoWhen$WhenCoordinator.signalError(MonoWhen.java:172)
	at reactor.core.publisher.MonoWhen$WhenInner.onError(MonoWhen.java:288)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onError(FluxMapFuseable.java:142)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onError(Operators.java:2063)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onError(FluxHandle.java:210)
	at reactor.core.publisher.Operators.error(Operators.java:198)
	at reactor.core.publisher.MonoError.subscribe(MonoError.java:53)
	at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
	at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
	at reactor.core.publisher.MonoCompletionStage.lambda$subscribe$0(MonoCompletionStage.java:92)
	at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
	at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: com.azure.core.amqp.implementation.RequestResponseChannelClosedException: Cannot send a message when request response channel is disposed.
	at com.azure.core.amqp.implementation.RequestResponseChannel.sendWithAck(RequestResponseChannel.java:309)
	at com.azure.core.amqp.implementation.RequestResponseChannel.sendWithAck(RequestResponseChannel.java:296)
	at com.azure.core.amqp.implementation.ClaimsBasedSecurityChannel.lambda$authorize$2(ClaimsBasedSecurityChannel.java:67)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:125)
	... 13 more

Here are logs +- 5 seconds around the error:

2023-04-21 10:05:37,201 INFO  [com.azu.cor.amq.imp.AmqpChannelProcessor] (parallel-1) {} {"az.sdk.message":"Error in AMQP channel processor.","connectionId":"MF_0bb2dd_1682055978561","entityPath":"$cbs","subscriberId":"un_a481f8_1682064332689"}
2023-04-21 10:05:37,201 ERROR [rea.cor.pub.Operators] (parallel-1) {} Operator called default onErrorDropped: reactor.core.Exceptions$ErrorCallbackNotImplemented: java.lang.RuntimeException: Unable to open send and receive link.
Caused by: java.lang.RuntimeException: Unable to open send and receive link.
	at com.azure.core.amqp.implementation.RequestResponseChannel.<init>(RequestResponseChannel.java:232)
	at com.azure.core.amqp.implementation.ReactorConnection.lambda$createRequestResponseChannel$18(ReactorConnection.java:404)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:113)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129)
	at reactor.core.publisher.Operators$MonoSubscriber.request(Operators.java:1906)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:171)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.request(FluxPeekFuseable.java:144)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.request(Operators.java:2158)
	at com.azure.core.amqp.implementation.AmqpChannelProcessor.requestUpstream(AmqpChannelProcessor.java:317)
	at com.azure.core.amqp.implementation.AmqpChannelProcessor.lambda$onError$4(AmqpChannelProcessor.java:213)
	at reactor.core.publisher.LambdaMonoSubscriber.onNext(LambdaMonoSubscriber.java:171)
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271)
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.util.concurrent.RejectedExecutionException: ReactorDispatcher instance is closed. Should not continue dispatching work to this reactor.
	at com.azure.core.amqp.implementation.ReactorDispatcher.throwIfSchedulerError(ReactorDispatcher.java:139)
	at com.azure.core.amqp.implementation.ReactorDispatcher.invoke(ReactorDispatcher.java:103)
	at com.azure.core.amqp.implementation.RequestResponseChannel.<init>(RequestResponseChannel.java:227)
	... 20 more
Collapse
2023-04-21 10:05:37,201 WARN  [com.azu.cor.amq.imp.AmqpChannelProcessor] (parallel-1) {} {"az.sdk.message":"Retry attempts exhausted or exception was not retriable.","exception":"Unable to open send and receive link.","connectionId":"MF_0bb2dd_1682055978561","entityPath":"$cbs","tryCount":1}
2023-04-21 10:05:37,200 INFO  [com.azu.cor.amq.imp.RequestResponseChannel] (boundedElastic-36) {} {"az.sdk.message":"Unable to schedule close work. Closing manually.","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs"}
2023-04-21 10:05:37,200 WARN  [com.azu.cor.amq.imp.RequestResponseChannel] (parallel-1) {} {"az.sdk.message":"Unable to open send and receive link.","exception":"Unable to open send and receive link.","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs"}
2023-04-21 10:05:37,200 WARN  [com.azu.cor.amq.imp.ReactorDispatcher] (boundedElastic-36) {} {"az.sdk.message":"ReactorDispatcher instance is closed. Should not continue dispatching work to this reactor.","exception":"ReactorDispatcher instance is closed. Should not continue dispatching work to this reactor.","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:37,200 WARN  [com.azu.cor.amq.imp.ReactorDispatcher] (parallel-1) {} {"az.sdk.message":"ReactorDispatcher instance is closed. Should not continue dispatching work to this reactor.","exception":"ReactorDispatcher instance is closed. Should not continue dispatching work to this reactor.","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:37,199 INFO  [com.azu.cor.amq.imp.AmqpChannelProcessor] (parallel-1) {} {"az.sdk.message":"Connection not requested, yet. Requesting one.","connectionId":"MF_0bb2dd_1682055978561","entityPath":"$cbs"}
2023-04-21 10:05:37,199 INFO  [com.azu.cor.amq.imp.AmqpChannelProcessor] (parallel-1) {} {"az.sdk.message":"Requesting from upstream.","connectionId":"MF_0bb2dd_1682055978561","entityPath":"$cbs","tryCount":0}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-12) {} {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_0bb2dd_1682055978561","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"Finished processing pending tasks.","namespace":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-12) {} {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_0bb2dd_1682055978561","isTransient":false,"isInitiatedByClient":true,"shutdownMessage":"Closing based on user-invoked close operation.","namespace":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-12) {} {"az.sdk.message":"onConnectionShutdown. Shutting down.","connectionId":"MF_0bb2dd_1682055978561","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"connectionId[MF_0bb2dd_1682055978561] Reactor selectable is disposed.","namespace":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.ReactorDispatcher] (reactor-executor-12) {} {"az.sdk.message":"Reactor selectable is being disposed.","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:36,691 WARN  [com.azu.cor.amq.imp.ReactorExecutor] (reactor-executor-12) {} {"az.sdk.message":"scheduleCompletePendingTasks - exception occurred while  processing events.\njava.lang.IllegalStateException\norg.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:112)\norg.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324)\norg.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:292)\ncom.azure.core.amqp.implementation.ReactorExecutor.lambda$scheduleCompletePendingTasks$1(ReactorExecutor.java:158)\nreactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)\nreactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)\njava.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\njava.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)\njava.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\njava.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\njava.base/java.lang.Thread.run(Thread.java:833)Cause: null\norg.apache.qpid.proton.engine.impl.EndpointImpl.decref(EndpointImpl.java:54)\norg.apache.qpid.proton.engine.impl.TransportImpl.unbind(TransportImpl.java:315)\norg.apache.qpid.proton.reactor.impl.IOHandler.onUnhandled(IOHandler.java:395)\norg.apache.qpid.proton.engine.BaseHandler.onTransportClosed(BaseHandler.java:84)\norg.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:200)\norg.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108)\norg.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324)\norg.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:292)\ncom.azure.core.amqp.implementation.ReactorExecutor.lambda$scheduleCompletePendingTasks$1(ReactorExecutor.java:158)\nreactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)\nreactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)\njava.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)\njava.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)\njava.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\njava.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\njava.base/java.lang.Thread.run(Thread.java:833)","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onTransportClosed","connectionId":"MF_0bb2dd_1682055978561","errorCondition":"n/a","errorDescription":"n/a","hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:36,691 INFO  [com.azu.cor.amq.imp.ReactorExecutor] (reactor-executor-12) {} {"az.sdk.message":"Processing all pending tasks and closing old reactor.","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:32,817 ERROR [com.azu.cor.amq.imp.RetryUtil] (Thread-61) {} Failed to create send link generate_historygenerate_history
Cannot send a message when request response channel is disposed.
2023-04-21 10:05:32,816 ERROR [com.azu.cor.amq.imp.RequestResponseChannel] (Thread-61) {} {"az.sdk.message":"Cannot send a message when request response channel is disposed.","exception":"Cannot send a message when request response channel is disposed.","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs"}
2023-04-21 10:05:32,816 INFO  [com.azu.ide.ClientSecretCredential] (Thread-61) {} Azure Identity => getToken() result for scopes [https://servicebus.azure.net/.default]: SUCCESS
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-12) {} {"az.sdk.message":"onConnectionError, Starting new reactor","exception":"java.lang.IllegalStateException, TrackingId: 19909c96-6df4-4f0e-8cef-8dc001dc5d36, at: 2023-04-21T10:05:32.690905380+02:00[Europe/Copenhagen], errorContext[NAMESPACE: myservicebus.servicebus.windows.net. ERROR CONTEXT: N/A]","connectionId":"MF_0bb2dd_1682055978561","namespace":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:32,690 WARN  [com.azu.cor.amq.imp.ReactorExecutor] (reactor-executor-12) {} {"az.sdk.message":"Unhandled exception while processing events in reactor, report this error.","exception":"java.lang.IllegalStateException","connectionId":"MF_0bb2dd_1682055978561"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onTransportClosed","connectionId":"MF_0bb2dd_1682055978561","errorCondition":"n/a","errorDescription":"n/a","hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onConnectionFinal","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionFinal.","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkFinal","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs:receiver","entityPath":"$cbs"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkFinal","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs:sender","entityPath":"$cbs"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionFinal.","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"generate_history"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkFinal","connectionId":"MF_0bb2dd_1682055978561","linkName":"generate_historygenerate_history","entityPath":"generate_history"}
2023-04-21 10:05:32,690 INFO  [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkFinal","connectionId":"MF_0bb2dd_1682055978561","linkName":"generate_historygenerate_history","entityPath":"generate_history"}
2023-04-21 10:05:32,690 INFO  [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (reactor-executor-12) {} {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}
2023-04-21 10:05:32,689 INFO  [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (reactor-executor-12) {} {"az.sdk.message":"Connection not requested, yet. Requesting one.","entityPath":"N/A"}
2023-04-21 10:05:32,689 INFO  [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (reactor-executor-12) {} {"az.sdk.message":"Channel is closed. Requesting upstream.","entityPath":"N/A"}
2023-04-21 10:05:32,689 INFO  [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-12) {} {"az.sdk.message":"Disposing of ReactorConnection.","connectionId":"MF_0bb2dd_1682055978561","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"Connection handler closed."}
2023-04-21 10:05:32,689 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onConnectionUnbound","connectionId":"MF_0bb2dd_1682055978561","hostName":"myservicebus.servicebus.windows.net","state":"CLOSED","remoteState":"CLOSED"}
2023-04-21 10:05:32,689 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onConnectionLocalClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:32,689 INFO  [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-12) {} {"az.sdk.message":"onConnectionRemoteClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:1eb22861a17e4ed3a2d948d8ad166f28_G1S1, SystemTracker:gateway5, Timestamp:2023-04-21T08:05:32","hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 10:05:32,688 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}
2023-04-21 10:05:32,688 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"cbs-session"}
2023-04-21 10:05:32,688 INFO  [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs:receiver","entityPath":"$cbs","state":"ACTIVE"}
2023-04-21 10:05:32,688 INFO  [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:1eb22861a17e4ed3a2d948d8ad166f28_G1S1, SystemTracker:gateway5, Timestamp:2023-04-21T08:05:32","linkName":"cbs:receiver","entityPath":"$cbs"}
2023-04-21 10:05:32,687 INFO  [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-12) {} {"az.sdk.message":"Transient error occurred. Retrying.","exception":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:1eb22861a17e4ed3a2d948d8ad166f28_G1S1, SystemTracker:gateway5, Timestamp:2023-04-21T08:05:32, errorContext[NAMESPACE: myservicebus.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 97]","connectionId":"MF_0bb2dd_1682055978561","entityPath":"$cbs","tryCount":0,"interval_ms":4511}
2023-04-21 10:05:32,684 WARN  [com.azu.cor.amq.imp.RequestResponseChannel] (reactor-executor-12) {} {"az.sdk.message":"Error in SendLinkHandler. Disposing unconfirmed sends.","exception":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:1eb22861a17e4ed3a2d948d8ad166f28_G1S1, SystemTracker:gateway5, Timestamp:2023-04-21T08:05:32, errorContext[NAMESPACE: myservicebus.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 97]","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs"}
2023-04-21 10:05:32,684 INFO  [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_0bb2dd_1682055978561","linkName":"cbs:sender","entityPath":"$cbs","state":"ACTIVE"}
2023-04-21 10:05:32,684 INFO  [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-12) {} {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":"amqp:connection:forced","errorDescription":"The connection was inactive for more than the allowed 300000 milliseconds and is closed by container 'LinkTracker'. TrackingId:1eb22861a17e4ed3a2d948d8ad166f28_G1S1, SystemTracker:gateway5, Timestamp:2023-04-21T08:05:32","linkName":"cbs:sender","entityPath":"$cbs"}
2023-04-21 10:05:32,683 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"generate_history"}
2023-04-21 10:05:32,683 INFO  [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-12) {} {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_0bb2dd_1682055978561","errorCondition":null,"errorDescription":null,"sessionName":"generate_history"}

To Reproduce
Unknown.

This happed to 1 out of 75 sent messages in a 3 hour interval. The failing message was sent at 10:05:03. A message was successfully sent before at 09:50.32, and after at 10:07:55.

Code Snippet

public Mono<Void> sendMessages(List<ServiceBusMessage> batch) {
    ServiceBusSenderAsyncClient serviceBusSenderAsyncClient = getServiceBusSenderAsyncClient(config);
    return serviceBusSenderAsyncClient.sendMessages(batch);
}

private ServiceBusSenderAsyncClient getServiceBusSenderAsyncClient(Config config) {
    return createServiceBusClientBuilder(config)
            .sender()
            .queueName(config.getValue("queue-name", String.class))
            .buildAsyncClient();
}

private ServiceBusClientBuilder createServiceBusClientBuilder(Config config) {
    TokenCredential credential = getTokenCredential(config);
    String namespace = config.getValue("namespace", String.class);

    ServiceBusClientBuilder serviceBusClientBuilder = new ServiceBusClientBuilder()
            .transportType(AmqpTransportType.AMQP_WEB_SOCKETS)
            .credential(namespace, credential)
            .proxyOptions(getAmqpProxyOptions(config));
    return serviceBusClientBuilder;
}

private ProxyOptions getAmqpProxyOptions(Config config) {
    Proxy proxy = getAmqpProxy(config);
    return new ProxyOptions(ProxyAuthenticationType.NONE, proxy, null, null);
}

private Proxy getAmqpProxy(Config config) {
    if (config.getOptionalValue("use-proxy-for-amqp-connection", Boolean.class).orElse(true)) {
        return new Proxy(Proxy.Type.HTTP, getInetSocketAddress(config));
    } else {
        return Proxy.NO_PROXY;
    }
}

private TokenCredential getTokenCredential(Config config) {
    return new ClientSecretCredentialBuilder()
            .tenantId(config.getValue("tenant-id", String.class))
            .clientId(config.getValue("client-id", String.class))
            .clientSecret(config.getValue("client-secret", String.class))
            .httpClient(getHttpClientForLogin(config))
            .build();
}

private HttpClient getHttpClientForLogin(Config config) {
    return new NettyAsyncHttpClientBuilder()
            .proxy(getHttpProxyOptions(config))
            .build();
}

private com.azure.core.http.ProxyOptions getHttpProxyOptions(Config config) {
    return new com.azure.core.http.ProxyOptions(com.azure.core.http.ProxyOptions.Type.HTTP, getInetSocketAddress(config));
}

private static InetSocketAddress getInetSocketAddress(Config config) {
    String proxyHost = config.getOptionalValue("proxy-host", String.class)
            .orElse("my-coperate-proxy");
    int proxyPort = config.getOptionalValue("proxy-port", Integer.class)
            .orElse(8080);
    return new InetSocketAddress(proxyHost, proxyPort);
}

Expected behavior
First of all that the error should not happen, but at the very least the message should have retried to send.

Setup (please complete the following information):

  • OS: registry.access.redhat.com/ubi8/openjdk-17
  • Library/Libraries: com.azure:azure-messaging-servicebus:7.13.0 and com.azure:azure-identity:1.5.4
  • Java version: 17
  • App Server/Environment: Kubernetes v1.24.11+af0420d
  • Frameworks: Quarkus 2.16.0

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

  • Bug Description Added
  • Repro Steps Added
  • Setup information Added

Activity

  1. github-actions
    added
    ClientThis issue points to a problem in the data-plane of the library.
    customer-reportedIssues that are reported by GitHub users external to the Azure organization.
    needs-team-triageWorkflow: This issue needs the team to triage.
    questionThe issue doesn't require a change to the product in order to be resolved. Most issues start as that
    Service Bus
    on Apr 25, 2023
  2. Josh Free (joshfree)
    assigned
    Anu Thomas (anuchandy)
    on Aug 1, 2023

  3. joshfree commented on Aug 1, 2023

    @joshfree
    Josh Free (joshfree)
    on Aug 1, 2023
    Member

    Anu Thomas (@anuchandy) could you please follow up with Andreas Petersen (@AndreasPetersen) on this issue?

  4. anuchandy commented on Aug 2, 2023

    @anuchandy
    Anu Thomas (anuchandy)
    on Aug 2, 2023
    Member

    Addressed in the pr #36227

  5. AndreasPetersen commented on Aug 3, 2023

    @AndreasPetersen
    Andreas Petersen (AndreasPetersen)
    on Aug 3, 2023
    Author

    Amazing, thanks Anu Thomas (@anuchandy) !

  6. anuchandy commented on Aug 21, 2023

    @anuchandy
    Anu Thomas (anuchandy)
    on Aug 21, 2023
    Member

    The august release is completed 7.14.3. Closing the ticket.

  7. Anu Thomas (anuchandy)
    closed this as completedon Aug 21, 2023
  8. github-actions
    locked and limited conversation to collaborators on Nov 19, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

ClientThis issue points to a problem in the data-plane of the library.Service Buscustomer-reportedIssues that are reported by GitHub users external to the Azure organization.needs-team-triageWorkflow: This issue needs the team to triage.questionThe issue doesn't require a change to the product in order to be resolved. Most issues start as that

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions