Log only what we need in INFO (too much logging by default)

[conniey]

• customers report that our logging is actually too detailed right now.
• Should we have an aka.ms link to a FAQ that also has info on how to collect enough data for a bug report?
• There are transient errors that happen in AMQP which are later recovered from in the library. These errors are propagated back to the user as warnings which may give them the impression that the library failed.

ie. If there are timeout exceptions that we recover from, can we just suppress them.

[conniey]

• Logging ReactorExecutor/ReactorDispatcher errors are not helpful because they almost always not the root cause of the actual issue.
• Logging transient errors that we recover from as errors.

[ki1729]

Request from customer as well to reduce our logging in INFO level - #20527
Tracking progress here

[jfurmankiewiczpros]

Still occurring in latest SDK, our logs are flooded with hundreds of thousands of messages like this

[boundedElastic-9] INFO com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor - prefetch: '8', requested: '1', linkCredits: '3', expectedTotalCredit: '8', queuedMessages:'5', creditsToAdd: '0', messageQueue.size(): '5'
[boundedElastic-9] INFO com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor - prefetch: '8', requested: '1', linkCredits: '3', expectedTotalCredit: '8', queuedMessages:'4', creditsToAdd: '1', messageQueue.size(): '4'
[boundedElastic-7] INFO com.azure.messaging.servicebus.implementation.ServiceBusReceiveLinkProcessor - prefetch: '8', requested: '1', linkCredits: '4', expectedTotalCredit: '8', queuedMessages:'4', creditsToAdd: '0', messageQueue.size(): '4'

ServiceBusReceiveLinkProcesor is definitely the culprit, changing the single line in there that logs this from INFO to DEBUG would be a godsend.

[joshfree]

Should we have an aka.ms link to a FAQ that also has info on how to collect enough data for a bug report?

Yes, as part of the logging cleanup; our logging of errors and exception messages should have embedded aka.ms links which point to anchors in a TROUBLESHOOTING.md. See how azure-identity has done this already (/cc @g2vinay) as a template.

[JorgeCupiV]

We also have a request from customer to reduce the logging in INFO level, or at least provide a mechanism to specifically ignore the INFO logs from Service Bus

[jfurmankiewiczpros]

I just tried upgrading to latest SDK and I think the logging has gotten worse!

See samples...ever operation logged as INFO. Please FIX THIS!
it's unusable in production.

49268376727","linkName":"cbs","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.handler.ReceiveLinkHandler - {"az.sdk.message":"Receiver link was never active. Closing endpoint states","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs","linkName":"cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Channel is closed. Requesting upstream.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Connection not requested, yet. Requesting one.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.ReactorConnection - {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs","linkName":"cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Next AMQP channel received, updating 0 current subscribers","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.handler.SendLinkHandler - {"az.sdk.message":"Sender link was never active. Closing endpoint states.","connectionId":"MF_0a5ddb_1649268376727","linkName":"cbs","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.handler.ReceiveLinkHandler - {"az.sdk.message":"Receiver link was never active. Closing endpoint states","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs","linkName":"cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Channel is closed. Requesting upstream.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Connection not requested, yet. Requesting one.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.ReactorConnection - {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs","linkName":"cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}
[reactor-executor-1] INFO com.azure.core.amqp.implementation.AmqpChannelProcessor - {"az.sdk.message":"Next AMQP channel received, updating 0 current subscribers","connectionId":"MF_0a5ddb_1649268376727","entityPath":"$cbs"}

[ki1729]

Request to include additional logs indicating processor restart - #28859
Tracking progress here

[madossan01]

The current INFO logs from Service Bus SDK are too verbose, here’s an example on what we see at the logging:

2022-04-06 13:40:00.371 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler : onConnectionRemoteClose connectionId[MF_f36194_1649270398347] hostname[SERVICE_BUS_URL] errorCondition[null] errorDescription[null]
2022-04-06 13:40:00.371 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler : onTransportClosed hostname[SERVICE_BUS_URL], connectionId[MF_f36194_1649270398347], error[n/a]
2022-04-06 13:40:00.372 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.CustomIOHandler : onTransportClosed connectionId[MF_f36194_1649270398347], hostname[SERVICE_BUS_URL]
2022-04-06 13:40:00.372 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler : onConnectionUnbound hostname[SERVICE_BUS_URL], connectionId[MF_f36194_1649270398347], state[CLOSED], remoteState[CLOSED]
2022-04-06 13:40:00.372 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.SessionHandler : onSessionFinal connectionId[MF_f36194_1649270398347], entityName[SERVICE_BUS_TOPIC/subscriptions/SERVICE_BUS_TOPIC_SUBSCRIPTION], condition[null], description[null]
2022-04-06 13:40:00.372 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.SendLinkHandler : onLinkFinal connectionId[MF_f36194_1649270398347], linkName[cbs:sender]
2022-04-06 13:40:00.373 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler : onLinkFinal connectionId[MF_f36194_1649270398347], linkName[cbs:receiver]
2022-04-06 13:40:00.373 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Channel is closed. Requesting upstream.
2022-04-06 13:40:00.373 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Connection not requested, yet. Requesting one.
2022-04-06 13:40:00.374 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection : connectionId[MF_f36194_1649270398347] entityPath[$cbs] linkName[cbs] Emitting new response channel.
2022-04-06 13:40:00.374 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Setting next AMQP channel.
2022-04-06 13:40:00.375 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Next AMQP channel received, updating 1 current subscribers
2022-04-06 13:40:00.375 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.SendLinkHandler : onLinkFinal connectionId[MF_f36194_1649270398347], linkName[cbs:sender]
2022-04-06 13:40:00.376 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler : onLinkFinal connectionId[MF_f36194_1649270398347], linkName[cbs:receiver]
2022-04-06 13:40:00.376 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.SessionHandler : onSessionFinal connectionId[MF_f36194_1649270398347], entityName[cbs-session], condition[null], description[null]
2022-04-06 13:40:00.376 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ConnectionHandler : onConnectionFinal connectionId[MF_f36194_1649270398347] hostname[SERVICE_BUS_URL] errorCondition[null] errorDescription[null]
2022-04-06 13:40:00.377 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.SendLinkHandler : connectionId[MF_f36194_1649270398347] linkName[cbs] entityPath[$cbs] Sender link was never active. Closing endpoint states.
2022-04-06 13:40:00.378 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler : connectionId[MF_f36194_1649270398347] linkName[cbs] entityPath[$cbs] Receiver link was never active. Closing endpoint states.
2022-04-06 13:40:00.378 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Channe
2022-04-06 13:40:00.380 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.handler.ReceiveLinkHandler : connectionId[MF_f36194_1649270398347] linkName[cbs] entityPath[$cbs] Receiver link was never active. Closing endpoint states.
2022-04-06 13:40:00.381 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Channel is closed. Requesting upstream.
2022-04-06 13:40:00.381 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Connection not requested, yet. Requesting one.
2022-04-06 13:40:00.382 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.ReactorConnection : connectionId[MF_f36194_1649270398347] entityPath[$cbs] linkName[cbs] Emitting new response channel.
2022-04-06 13:40:00.382 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Setting next AMQP channel.
2022-04-06 13:40:00.382 INFO 16140 --- [ctor-executor-3] c.a.c.a.i.RequestResponseChannel:$cbs : namespace[MF_f36194_1649270398347] entityPath[$cbs]: Next AMQP channel received, updating 1 current subscribers

This log was generated for:
Language: Java 11.0.2 with Spring Boot 2.5.6
azure-spring-boot-bom : 3.10.2

Expected Behavior:
The Service Bus SDK's INFO logs should be reduced to minimum that describes the behavior. For example:
• New client has been opened
• Current client has been closed
• Current open connections are:

It also could be provided option to enable/disable.

[Rayzbam]

Any update on this case ?
We would like to upgrade our app with this version, but that verbosity can't be in a PRODUCTION environment.
If you're using Application Insights for example, all these logs will automatically be sent in AI if you've setted your ILoggerProvider in your logging providers.

I mean in INFO, we don't have to have these kind of logs.
INFO is related to StartProcessingAsync, StopProcessingAsync, CloseAsync ..
All which is link to AMQP (or other transport), or transient operations (like a send or a manual receive operation) should be in DEBUG imo.

[eric-maynard]

@anuchandy Is there any update here?

[ykarikos]

@conniey Is the excess logging going to be addressed in future releases?

[Perl99]

Could you also hide onErrorDropped from logs? This happens when the connection is idle for a long time, but it does not seem like an error actually.
I have found a similar issue that was fixed for CosmosDB client: #10401

Example stack trace:

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 io.micrometer.core.instrument.composite.CompositeTimer.recordCallable(CompositeTimer.java:77)
at io.micrometer.core.instrument.Timer.lambda$wrap$1(Timer.java:162)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)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)
... 23 more

[robsonkades]

any update on this?

[conniey]

• Log reduction by using ConnectionCache and MessageFlux.

Create new issue if we have concrete areas to reduce logging.