[Event Hubs] Update logging to match design spec.

[conniey]

Update logging in azure-core-amqp and azure-messaging-eventhubs to align with guidelines in:
https://azure.github.io/azure-sdk/java_implementation.html#logging

[srnagar]

@conniey If we are using ClientLogger everywhere, shouldn't that take care of logging as per spec?

[conniey]

@srnagar This was around when we log use the client logger to log statements. I know there are times we use .info when it should be a .trace, and other times when we don't write errors.
https://azure.github.io/azure-sdk/java_implementation.html#logging

[mclay]

@conniey pls assign me this issue and elaborate a bit more on the the remaining things to do for this issues and also the affected modules

[conniey]

@mclay Hey. I was taking a look at this task and it requires more in-depth knowledge of what exceptions are recoverable/normal and which are fatal. I am not sure how comfortable you'd feel delving into the inner workings of Event Hubs and our core AMQP library. This may be more than just a "up-for-grabs" task.

One example is https://github.com/Azure/azure-sdk-for-java/blob/master/sdk/eventhubs/azure-messaging-eventhubs/src/main/java/com/azure/messaging/eventhubs/EventHubPartitionAsyncConsumer.java#L86 where, depending on the exception type, if it is an AmqpException, it could be retriable or not. So we would add some logic to log it appropriately.

Let me know if you're still interested in helping out with this task. :)

[mclay]

@conniey yes i am interested. Could you please give me some more information about the intention respectively goal of this task.

[mclay]

@conniey do you have additional informations for me to consider or can i start right away with this one

[conniey]

This task intends that if users are using our library, and something occurs in it, informational, trace, warning, error, they can diagnose it by setting AZURE_LOG_LEVEL environment variable. Most of the logging is done in azure-core-amqp. It was a carryover from our first SDK. so some of the logging may not match the specs.

Yes. please go ahead and start. :)

[mclay]

Thanks for the additional infos. Just to be sure - the due date is end of January right?

[conniey]

I slotted it to be done end of January, but if it falls through, it won't be a problem because this is not a high priority task. There is a bunch of logging in place already; it's just not consistent and pretty arbitrary. :) So, I hope you don't feel rushed or anything.

[joshfree]

@mclay thanks for picking up this issue. 😄 Have you had time to make progress on this?

[mclay]

@joshfree busy times.. if it's not too late for you i would like to start this one next

[in-fke]

Any progress on this? "Regular" setup logs way too verbose in my opinion.
Any hint for a workaround? (besides configuring log level)
As "regular" Java developer I do not expect for a 3rd party component to log on such a verbose level.

Just to give a few examples

2021-03-05T16:42:53,696 INFO  [single-1] implementation.handler.ConnectionHandler:335 onConnectionRemoteOpen hostname[iothub-ns-in-sphinx-7486724-7d375b9cc5.servicebus.windows.net:443], connectionId[MF_6a5edf_1614958972821], remoteContainer[0ceb9d6fe37b43429ad438cbbac0a121_G21]
2021-03-05T16:42:53,697 INFO  [single-1] eventhubs.implementation.EventHubConnectionProcessor:335 namespace[iothub-ns-in-sphinx-7486724-7d375b9cc5.servicebus.windows.net] entityPath[in-sphinx-hub]: Channel is now active.
2021-03-05T16:42:53,697 INFO  [single-1] implementation.handler.SessionHandler:335 onSessionRemoteOpen connectionId[MF_6a5edf_1614958972821], entityName[in-sphinx-hub/ConsumerGroups/$default/Partitions/1], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
2021-03-05T16:42:53,698 INFO  [single-1] amqp.implementation.ReactorConnection:109 Setting CBS channel.
2021-03-05T16:42:53,698 INFO  [single-1] amqp.implementation.ReactorConnection:335 Emitting new response channel. connectionId: MF_6a5edf_1614958972821. entityPath: $cbs. linkName: cbs.
2021-03-05T16:42:53,699 INFO  [single-1] amqp.implementation.RequestResponseChannel<cbs-session>:335 namespace[MF_6a5edf_1614958972821] entityPath[$cbs]: Setting next AMQP channel.
2021-03-05T16:42:53,699 INFO  [single-1] amqp.implementation.RequestResponseChannel<cbs-session>:335 namespace[MF_6a5edf_1614958972821] entityPath[$cbs]: Next AMQP channel received, updating 0 current subscribers
2021-03-05T16:42:53,759 INFO  [single-1] implementation.handler.ReceiveLinkHandler:335 onLinkLocalOpen connectionId[MF_6a5edf_1614958972821], 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}]
2021-03-05T16:42:53,822 INFO  [single-1] implementation.handler.SessionHandler:335 onSessionRemoteOpen connectionId[MF_6a5edf_1614958972821], entityName[cbs-session], sessionIncCapacity[0], sessionOutgoingWindow[2147483647]
2021-03-05T16:42:53,822 INFO  [single-1] implementation.handler.SendLinkHandler:335 onLinkRemoteOpen connectionId[MF_6a5edf_1614958972821], entityPath[$cbs], linkName[cbs:sender], remoteTarget[Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}]
2021-03-05T16:42:53,822 INFO  [single-1] amqp.implementation.RequestResponseChannel<cbs-session>:335 namespace[MF_6a5edf_1614958972821] entityPath[$cbs]: Channel is now active.
2021-03-05T16:42:53,822 INFO  [single-1] implementation.handler.ReceiveLinkHandler:335 onLinkRemoteOpen connectionId[MF_6a5edf_1614958972821], 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}]
2021-03-05T16:42:53,822 INFO  [single-1] amqp.implementation.RequestResponseChannel<cbs-session>:335 namespace[MF_6a5edf_1614958972821] entityPath[$cbs]: Channel is now active.
2021-03-05T16:42:54,014 INFO  [single-1] amqp.implementation.ReactorSession:335 Creating a new receiver link with linkName 1_741503_1614958972825
2021-03-05T16:42:54,015 INFO  [single-1] eventhubs.implementation.AmqpReceiveLinkProcessor:335 linkName[1_741503_1614958972825] entityPath[in-sphinx-hub/ConsumerGroups/$default/Partitions/1]. Setting next AMQP receive link.
2021-03-05T16:42:54,016 INFO  [single-1] messaging.eventhubs.EventHubConsumerAsyncClient:335 connectionId[MF_6a5edf_1614958972821] linkName[1_741503_1614958972825]: Creating receive consumer for partition '1'
2021-03-05T16:42:54,016 INFO  [single-1] amqp.implementation.ReactorSession:335 linkName[1_741503_1614958972825] entityPath[in-sphinx-hub/ConsumerGroups/$default/Partitions/1]: Returning existing receive link.
2021-03-05T16:42:54,076 INFO  [single-1] implementation.handler.ReceiveLinkHandler:335 onLinkLocalOpen connectionId[MF_6a5edf_1614958972821], entityPath[in-sphinx-hub/ConsumerGroups/$default/Partitions/1], linkName[1_741503_1614958972825], localSource[Source{address='in-sphinx-hub/ConsumerGroups/$default/Partitions/1', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter={apache.org:selector-filter:string=UnknownDescribedType{descriptor=apache.org:selector-filter:string, described=amqp.annotation.x-opt-offset > '@latest'}}, defaultOutcome=null, outcomes=null, capabilities=null}]
2021-03-05T16:42:54,201 INFO  [single-1] implementation.handler.ReceiveLinkHandler:335 onLinkRemoteOpen connectionId[MF_6a5edf_1614958972821], entityPath[in-sphinx-hub/ConsumerGroups/$default/Partitions/1], linkName[1_741503_1614958972825], remoteSource[Source{address='in-sphinx-hub/ConsumerGroups/$default/Partitions/1', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter={apache.org:selector-filter:string=org.apache.qpid.proton.codec.DecoderImpl$UnknownDescribedType@73d7a0f0}, defaultOutcome=null, outcomes=null, capabilities=null}]
2021-03-05T16:42:54,201 INFO  [single-1] eventhubs.implementation.AmqpReceiveLinkProcessor:335 Link 1_741503_1614958972825 is now active with 500 credits.

2021-03-05T16:42:52,817 INFO  [elastic-2] eventhubs.implementation.PartitionProcessor:335 Initializing partition processor for partition 1
2021-03-05T16:42:52,817 INFO  [elastic-2] messaging.eventhubs.PartitionPumpManager:335 Starting event processing from offset[@latest], sequenceNumber[null], enqueuedTime[null], isInclusive[false] for partition 1
2021-03-05T16:42:52,821 INFO  [elastic-2] messaging.eventhubs.EventHubClientBuilder:335 connectionId[MF_6a5edf_1614958972821]: Emitting a single connection.
2021-03-05T16:42:52,822 INFO  [elastic-2] eventhubs.implementation.EventHubConnectionProcessor:335 namespace[iothub-ns-in-sphinx-7486724-7d375b9cc5.servicebus.windows.net] entityPath[in-sphinx-hub]: Setting next AMQP channel.
2021-03-05T16:42:52,822 INFO  [elastic-2] eventhubs.implementation.EventHubConnectionProcessor:335 namespace[iothub-ns-in-sphinx-7486724-7d375b9cc5.servicebus.windows.net] entityPath[in-sphinx-hub]: Next AMQP channel received, updating 0 current subscribers
2021-03-05T16:42:52,825 INFO  [elastic-2] eventhubs.implementation.AmqpReceiveLinkProcessor:109 Setting new subscription for receive link processor
2021-03-05T16:42:52,825 INFO  [elastic-2] eventhubs.implementation.AmqpReceiveLinkProcessor:109 Requesting a new AmqpReceiveLink from upstream.
2021-03-05T16:42:52,825 INFO  [elastic-2] messaging.eventhubs.EventHubConsumerAsyncClient:335 connectionId[MF_6a5edf_1614958972821] linkName[1_741503_1614958972825]: Creating receive consumer for partition '1'
2021-03-05T16:42:52,826 INFO  [elastic-2] amqp.implementation.ReactorConnection:335 connectionId[MF_6a5edf_1614958972821]: Creating and starting connection to proxy:7011
2021-03-05T16:42:52,828 INFO  [elastic-2] amqp.implementation.ReactorExecutor:335 connectionId[MF_6a5edf_1614958972821], message[Starting reactor.]
2021-03-05T16:42:52,828 INFO  [elastic-2] amqp.implementation.AzureTokenManagerProvider:335 Creating new token manager for audience[amqp://iothub-ns-in-sphinx-7486724-7d375b9cc5.servicebus.windows.net/in-sphinx-hub/ConsumerGroups/$default/Partitions/1], resource[in-sphinx-hub/ConsumerGroups/$default/Partitions/1]

Related issues:
#1991
#7774
#8501
#9122
#17038
#17885
#19278

Looks like this seems to bother others as well in different ways.