How to print the retry log for the Service Bus Queue(Java)

[kensinzl]

Query/Question

I am using Java SDK for the Azure Service Bus Queue.

       <dependency>
            <groupId>com.azure</groupId>
            <artifactId>azure-sdk-bom</artifactId>
            <version>1.2.13</version>
            <type>pom</type>
            <scope>import</scope>
       </dependency>
       <dependency>
 	    <groupId>com.azure</groupId>
 	    <artifactId>azure-messaging-servicebus</artifactId>
 	</dependency>

The following is my re-try configuration for the queue, but I can not find any printed log, something like re-try first time, re-try second times.

Question 1: how to print out the re-try log because I want to verify it actually re-try during some cases?

new ServiceBusClientBuilder().
        retryOptions(new AmqpRetryOptions().
                setMode(AmqpRetryMode.FIXED).
                setMaxRetries(retryMaxCount).
                setTryTimeout(Duration.ofMillis(operationTimeoutInMs)).
                setDelay(Duration.ofMillis(retryDelayInMs)).
                setMaxDelay(Duration.ofMillis(maxRetryDelayInMs))
                ).
        connectionString(AzureCommonConfiguration.getServiceBusConnStr())
        .sender()

Question 2: how to do not print the following logs, for me, they are too verbose, too many logs from a single send message action?

Majority of the logs include "az.sdk.message" and from com.azure.messaging.* or com.azure.core.amqp.*

01:08:36,324 INFO  [com.azure.messaging.servicebus.implementation.ServiceBusConnectionProcessor] (default task-1) {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}

01:08:36,339 INFO  [com.azure.messaging.servicebus.ServiceBusClientBuilder] (default task-1) # of open clients with shared connection: 1

01:08:38,074 INFO  [com.azure.messaging.servicebus.ServiceBusClientBuilder] (default task-1) # of open clients with shared connection: 2

01:08:39,343 INFO  [com.azure.core.amqp.implementation.ReactorConnection] (default task-1) {"az.sdk.message":"Creating and starting connection.","connectionId":"MF_4ac1d3_1714439316128","hostName":"ecoconnect-mintaka.servicebus.windows.net","port":5671}

01:08:39,440 INFO  [com.azure.core.amqp.implementation.ReactorExecutor] (default task-1) {"az.sdk.message":"Starting reactor.","connectionId":"MF_4ac1d3_1714439316128"}

01:08:39,454 INFO  [com.azure.core.amqp.implementation.handler.ConnectionHandler] (reactor-executor-1) {"az.sdk.message":"onConnectionInit","connectionId":"MF_4ac1d3_1714439316128","hostName":"ecoconnect-mintaka.servicebus.windows.net","namespace":"ecoconnect-mintaka.servicebus.windows.net"}

01:08:39,458 INFO  [com.azure.core.amqp.implementation.handler.ReactorHandler] (reactor-executor-1) {"az.sdk.message":"reactor.onReactorInit","connectionId":"MF_4ac1d3_1714439316128"}

01:08:39,460 INFO  [com.azure.core.amqp.implementation.handler.ConnectionHandler] (reactor-executor-1) {"az.sdk.message":"onConnectionLocalOpen","connectionId":"MF_4ac1d3_1714439316128","hostName":"ecoconnect-mintaka.servicebus.windows.net"}

01:08:39,856 INFO  [com.azure.core.amqp.implementation.handler.ConnectionHandler] (reactor-executor-1) {"az.sdk.message":"onConnectionBound","connectionId":"MF_4ac1d3_1714439316128","hostName":"ecoconnect-mintaka.servicebus.windows.net","peerDetails":"ecoconnect-mintaka.servicebus.windows.net:5671"}

01:08:45,345 INFO  [com.azure.core.amqp.implementation.handler.ConnectionHandler] (reactor-executor-1) {"az.sdk.message":"onConnectionRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","hostName":"ecoconnect-mintaka.servicebus.windows.net","remoteContainer":"bfd514e9bc5441e487ab8a9ec16201c7_G22"}

01:08:45,347 INFO  [com.azure.messaging.servicebus.implementation.ServiceBusConnectionProcessor] (reactor-executor-1) {"az.sdk.message":"Channel is now active.","entityPath":"N/A"}

01:08:45,769 INFO  [com.azure.core.amqp.implementation.handler.SessionHandler] (reactor-executor-1) {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","sessionName":"mintaka-point-data-queue","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}

01:08:45,786 INFO  [com.azure.core.amqp.implementation.ReactorConnection] (reactor-executor-1) {"az.sdk.message":"Setting CBS channel.","connectionId":"MF_4ac1d3_1714439316128"}

01:08:45,842 INFO  [com.azure.core.amqp.implementation.handler.SessionHandler] (reactor-executor-1) {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","sessionName":"cbs-session","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}

01:08:45,857 INFO  [com.azure.core.amqp.implementation.ReactorConnection] (reactor-executor-1) {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_4ac1d3_1714439316128","entityPath":"$cbs","linkName":"cbs"}
01:08:45,857 INFO  [com.azure.core.amqp.implementation.AmqpChannelProcessor] (reactor-executor-1) {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_4ac1d3_1714439316128","entityPath":"$cbs"}

01:08:45,869 INFO  [com.azure.core.amqp.implementation.AmqpChannelProcessor] (reactor-executor-1) {"az.sdk.message":"Next AMQP channel received.","connectionId":"MF_4ac1d3_1714439316128","entityPath":"$cbs","subscriberId":"un_01e4c1_1714439325794"}

01:08:45,925 INFO  [com.azure.core.amqp.implementation.handler.SendLinkHandler] (reactor-executor-1) {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","linkName":"cbs:sender","entityPath":"$cbs","remoteTarget":"Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}"}

01:08:45,927 INFO  [com.azure.core.amqp.implementation.AmqpChannelProcessor] (reactor-executor-1) {"az.sdk.message":"Channel is now active.","connectionId":"MF_4ac1d3_1714439316128","entityPath":"$cbs"}

01:08:45,930 INFO  [com.azure.core.amqp.implementation.handler.ReceiveLinkHandler] (reactor-executor-1) {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","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}"}

01:08:45,996 INFO  [com.azure.core.amqp.implementation.ActiveClientTokenManager] (reactor-executor-1) {"az.sdk.message":"Scheduling refresh token task.","scopes":"amqp://ecoconnect-mintaka.servicebus.windows.net/mintaka-point-data-queue"}

01:08:46,011 INFO  [com.azure.core.amqp.implementation.ReactorSession] (reactor-executor-1) {"az.sdk.message":"Creating a new send link.","connectionId":"MF_4ac1d3_1714439316128","linkName":"mintaka-point-data-queuemintaka-point-data-queue","sessionName":"mintaka-point-data-queue"}

01:08:46,090 INFO  [com.azure.messaging.servicebus.ServiceBusSenderAsyncClient] (reactor-executor-1) {"az.sdk.message":"Sending batch.","batchSize":1}

01:08:46,098 INFO  [com.azure.core.amqp.implementation.handler.SendLinkHandler] (reactor-executor-1) {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_4ac1d3_1714439316128","linkName":"mintaka-point-data-queuemintaka-point-data-queue","entityPath":"mintaka-point-data-queue","remoteTarget":"Target{address='mintaka-point-data-queue', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}"}

Thank you so much to read here, thank you in advance.

[github-actions[bot]]

@anuchandy @conniey @lmolkova

[github-actions[bot]]

Thank you for your feedback. Tagging and routing to the team member best able to assist.

[lmolkova]

@kensinzl thank you for reporting this!

The logs you shared are not from one send, but from the first send and include logs written for establishing the connection.

Connection retry logs are written in ReactorConnectionCache if you use one of the latest versions, or by the AmqpChannelProcessor and should come from the class that overrides it - ServiceBusConnectionProcessor if you use an older version

There are other reasons beyond connection errors to retry operations but we don't have a central marker indicating a retry or a callback to log things in the case of a retry.

You may also find suggestions on how to reduce number of logs in the ServiceBus troubleshooting guide

[github-actions[bot]]

Hi @kensinzl. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text "/unresolve" to remove the "issue-addressed" label and continue the conversation.

[kensinzl]

@lmolkova

Thank you for your explanation.

If possible, could you please share the code on how to print out the logs for a re-try of the service bus queue because I googled your Azure Java document, but there are no examples for reference, eg: AmqpChannelProcessor or ReactorConnectionCache

[kensinzl]

/unresolve

[kensinzl]

May I confirm how is going on for my latest comment, thanks so much,

[anuchandy]

The AmqpChannelProcessor or ReactorConnectionCache are the types that retries in "Connection" level, your log configuration already seems to collect logs from these types (per the logs snippet posted above). There are other retries (e.g., in "Link" level - Sender, Receiver, Auth etc..), but as mentioned in the previous comment, we don't have a central marker indicating those retries or a callback to log in the case of such a retry, i.e., some parts of the retries in Sender/Receiver are not logged.

[kensinzl]

@anuchandy

Thanks for the reply. I am still confused for the response,

I want to get a straight response for the following

1. does ServiceBusClientBuilder have the re-try log in your Java SDK? if has, how can I let these logs been printed?

new ServiceBusClientBuilder().
        retryOptions(new AmqpRetryOptions().
                setMode(AmqpRetryMode.FIXED).
                setMaxRetries(retryMaxCount).
                setTryTimeout(Duration.ofMillis(operationTimeoutInMs)).
                setDelay(Duration.ofMillis(retryDelayInMs)).
                setMaxDelay(Duration.ofMillis(maxRetryDelayInMs))
                ).
        connectionString(AzureCommonConfiguration.getServiceBusConnStr())
        .sender()

2. how I can do not print the azure log, eg: "az.sdk.message" and from com.azure.messaging.* or com.azure.core.amqp.*?

Thank you so much.

[anuchandy]

The SenderClient will do the retries, but these retries are "not logged or printed", I hope this clarifies the earlier comments.

Normally, when an error happens in the internal connection (it is called amqp-sender-link) associated with the queue, then the Server will disconnect this amqp-sender-link. The retry in the SenderClient or the next send call will re-open the amqp-sender-link. While retry is not logged explicitly, you will see log such as onLinkRemoteOpen (by the retry) appearing if Service disconnects.

Logging in Service Bus (and Event Hubs) will be spread among two namespaces - "com.azure.messaging.", "com.azure.core.amqp.". The onLinkRemoteOpen is logged within com.azure.core.amqp. namespace under com.azure.core.amqp.implementation.handler.SendLinkHandler.

If you wish to adjust (e.g., filter out) the logging, it must be done using Log4J or Logback configuration (depending on which logging framework your application uses). The library uses the well-established SLF4J logging framework in Java world. Here is a reference logging configuration, here is references to how to add filters for log4j and Logback.

[anuchandy]

Closing given queries are answered.