[Event Hubs] Map all logging to log levels

[ramya-rao-a]

In order to support the feature where we let users set loglevels, we need to re-visit all the logging we do. They need to be updated such that we know what combination of different log modules should be used in the enable() method of the debug package for each log level.

For more context on this, please see the plan outlined in #2662 (comment)

Log levels generally are

• None
• Error
• Warning
• Info
• Verbose

For example,

• Verbose would map to *
• we dont have anything for "warning" at the moment, we need to review what exactly will fall under the "warning" category and make the necessary changes
• Info would map to azure:event-hubs:*
• Error would map to azure:event-hubs:error. This needs review as well, because today we use log.error() to log non errors as well.

[ramya-rao-a]

Please revisit the latest guidelines around logging before starting making any code changes here

[chradek]

Summary

The @azure/event-hubs library currently supports logging through the debug module.
The library implemented logging prior to the general logging guidelines were published.
The areas below will describe an attempt to bring @azure/event-hubs logging in line with our guidelines.

Supported Log Channels

Proposal

The event-hubs library should only support the following log channels and they must be exposed to the user:

export const logError = debug("azure:event-hubs:error");
export const logWarning = debug("azure:event-hubs:warning");
export const logInfo = debug("azure:event-hubs:info");
export const logVerbose = debug("azure:event-hubs:verbose");

A user likely doesn't know or care about individual components of a library.
Each feature-level log channel we create also needs seperate channels for each log level.
They also need to be exposed directly to the user so they can configure custom logging.
Also with the current SDK log channels, the service-level log channels would never be used
because only the feature-level log channels would be written to.
This can become confusing to a customer then that wants to customize logging for the library.

Using only a service-level log channel keeps the number of channels we expose relatively small
and makes it easier to enable/customize logging for the library.

Background

The event hubs sdk has existing log channels that are used by the SDK today:
https://github.com/Azure/azure-sdk-for-js/blob/%40azure/event-hubs_5.0.0-preview.2/sdk/eventhub/event-hubs/src/log.ts

The guidelines specify the following with regards to naming and creating log channels:

DO prefix channel names with azure:<service-name>.

DO create log channels for the following log levels with the following channel name suffixes:

• Error: :error
• Warning: :warning
• Info: :info
• Verbose: :verbose

YOU MAY have additional log channels, for example, to log from separate components. However, these channels MUST still provide the three log levels from above for each subchannel.

Enabling Log Levels

Proposal

The guidelines around enabling log levels are not yet finalized.
With this in mind, I'm not sure we should attempt to enable logging for log levels other than those explicitly defined.

Take the following log levels defined in the guidelines:

• Error: :error
• Warning: :warning
• Info: :info
• Verbose: :verbose

We might expect that if a user enables azure:event-hubs:warning, that azure:event-hubs:error should also be enabled.
To enable both of these, users can instead specify the azure:event-hubs:(warning|error) as their DEBUG environment variable.

Using Log Levels

Proposal

Error

I'm not aware of any known scenarios in event-hubs where we could detect an error the user's application
could not recover from.
As such, I don't think we should be using the error log channel at this time.

Warning

Most places where we use log.error today would be good candidates for log.warning, with a few exceptions.

We should use the warning log level anywhere in our code that we catch an error, provided it:

• will not be automatically retried. These should be sent to the verbose channel.
• is not an AbortError. These should be sent to the info channel.

Also note that stack traces should be sent to the verbose channel.

Example:

async function foo(abortSignal?: AbortSignalLike): Promise<void> {
  try {
    return await bar(abortSignal);
  } catch (err) {
    if (err.name === 'AbortError') {
      log.info(err.message);
    } else if (err.retryable && canStillRetry) {
      // assuming we will automatically retry this error...
      log.verbose(err.message, err.stack);
    } else {
      log.warning(err.message);
      log.verbose(err.stack);
    }
    throw err;
  }
}

Info

Many places where we currently use a feature log channel should use the info log channel.
As mentioned in the warning section, AbortError should also use the info log channel.

This channel is meant to be used when a function operates normally.

For example, the onMessage handler used by receiveBatch logs a message just before returning a successful response
and is a good candidate for the info channel.

azure-sdk-for-js/sdk/eventhub/event-hubs/src/receiver.ts

Lines 348 to 354 in 404347b

	log.batching(
	"[%s] Batching Receiver '%s', %d messages received within %d seconds.",
	this._context.connectionId,
	this._baseConsumer && this._baseConsumer.name,
	receivedEvents.length,
	maxWaitTimeInSeconds
	);

Verbose

The verbose channel is meant for logging information that's useful for troubleshooting.
Many places where we currently use a feature log channel for non-happy-path scenarios should use the verbose channel.
Stack traces for errors or warnings should also be sent to the verbose channel.

For example, the setTimeout invocation used by receiveBatch logs a message.
This is useful to know when troubleshooting but doesn't provide value in an application that is running normally.

azure-sdk-for-js/sdk/eventhub/event-hubs/src/receiver.ts

Lines 374 to 380 in 404347b

	const msg = "[%s] Setting the wait timer for %d seconds for receiver '%s'.";
	log.batching(
	msg,
	this._context.connectionId,
	maxWaitTimeInSeconds,
	this._baseConsumer && this._baseConsumer.name
	);

Background

The SDK guidelines specify the following rules for determining which log level to write to:

DO use the Error channel for failures that the application is unlikely to recover from (out of memory, etc.).

DO use the Warning channel when a function fails to perform its intended task.
This generally means that the function will raise an exception.
Do not include occurrences of self-healing events (for example, when a request will be automatically retried).

DO use the Info channel when a function operates normally.

DO use the Verbose channel for detailed troubleshooting scenarios.
This is primarily intended for developers or system administrators to diagnose specific failures.

DO log to the Info channel if a service call is cancelled.

DO log exceptions thrown to the Warning channel.
Additionally, send stack trace information to the Verbose channel.

[chradek]

Work has been started in #5401 but needs work due to some major refactoring that's occurred.