Logging in Azure SDK

Azure SDK logging

User-facing content for this wiki page has been relocated to https://docs.microsoft.com/azure/developer/java/sdk/logging-overview.

Setting an HttpLogDetailLevel

Regardless of the logging mechanism used, if a client builder offers the ability to set HttpLogOptions, these options must additionally be configured to output any logs. An HttpLogDetailLevel must be specifed to indicate what information should be logged. This value defaults to NONE, so if it is not specified, no logs will be output even if the logging framework or fallback logging is properly configured. For security reasons, headers and query parameters are redacted by default, so the log options must also be provided with a Set<String> indicating which headers and query parameters are safe to print. These value may be configured as shown below. The logging is set to print both body content and header values, all header values will be redacted except the value for the user specified metadata corresponding to the key "foo", and all query parameters will be redacted except for the sas token query parameter "sv" indicating the signed version of any sas which may be present.

new BlobClientBuilder().endpoint(<endpoint>)
            .httpLogOptions(new HttpLogOptions()
                .setLogLevel(HttpLogDetailLevel.BODY_AND_HEADERS)
                .setAllowedHeaderNames(Set.of("x-ms-meta-foo"))
                .setAllowedQueryParamNames(Set.of("sv")))
            .buildClient();

NOTE: This example uses a Storage client builder, but the principle applies for any builder which accepts HttpLogOptions. Furthermore, this example does not demonstrate the complete configuration of a client and is only intended to illustrate the configuration of logging. For more information on configuring clients, see the documentation on the respective builders.

Logging for Azure client library developers

ClientLogger wraps SLF4J API and provides default logging implementation, basic configuration, and ability to add key-value-pairs to log entries.

ClientLogger can only influence log messages. It's up to logging implementation (logback, log4j, JUL) to format a full message that contains a timestamp, level, thread, class, MDC.

If there is no SLF4J-compatible logging implementation on the classpath, ClientLogger falls back to home-grown DefaultLogger, in which case we control the layout and content of the whole log message.

Basic usage

• Create ClientLogger in classes that log things.
• Avoid creating ClientLogger on a hot path - use static instance instead.
• Use SLF4J placeholders ({}) instead of %s to avoid string formatting when logging at a given level is disabled.

ClientLogger logger = new ClientLogger(Application.class);

logger.info("hi there");
// 2022-02-23 15:01:55,015 INFO  [main] org.example.Application: hi there

// add dynamic values, avoid formatting strings - it will be done lazily depending on log level.
logger.info("hi there - my value: '{}'", "foo");
// 2022-02-23 15:01:55,043 INFO  [main] org.example.Application: hi there - my value: 'foo'

Exceptions

• Log exceptions once where they're first created or detected - don't log them again
• No need to call toString or add placeholder ({}) - just pass exception instance as the last parameter after log message
• Put the most important context in both the exception message and log entry.

// throw
throw logger.logThrowableAsError(new NullPointerException("'value' can't be null"));

// log only
try {
  // ...
} catch (Throwable t) {
  logger.warning("something bad happened", t);
}

The output depends on the log level and logging implementation. Below is an output from logback with the default configuration.

• if debug is enabled:

  2022-02-23 15:41:13,660 ERROR [main] org.example.Application: 'value' can't be null java.lang.NullPointerException: 'value' can't be null
     at org.example.Application.main(Application.java:19)
  
  2022-02-23 15:41:13,661 WARN  [main] org.example.Application: something bad happened
  'value' can't be null java.lang.NullPointerException: 'value' can't be null
     at org.example.Application.main(Application.java:24)
  

• otherwise:

  2022-02-23 15:40:01,761 ERROR [main] org.example.Application: 'value' can't be null 
  2022-02-23 15:40:01,761 WARN  [main] org.example.Application: something bad happened
  'value' can't be null 
  

Context

ClientLogger supports adding per-client and per-entry context. Contextual logging changes the output format to JSON.

• Use context when it could be beneficial to query or aggregate logs using given property. Use it for things like endpoints, connection-ids, client names.
• Keep context keys consistent across different classes (and related client libraries) to allow queries across all logs
• Use lazy value calculation.
• Prefer a static logger without global context to a logger with a global context. When there are multiple global context properties, it's likely more performant to have a per-instance logger with global context than a static logger. Benchmark with logging enabled to pick the best option.

// global context
ClientLogger loggerWithContext = new ClientLogger(Application.class, Map.of("foo", "bar"));
loggerWithContext.info("hi there - global context");
// 2022-02-23 15:41:13,664 INFO  [main] org.example.Application: {"az.sdk.message":"hi there - global context","foo":"bar"} 

// add log-entry context
loggerWithContext.atInfo()
        .addKeyValue("baz", 42)
        .log("hi there - global and log entry context");
// 2022-02-23 16:04:02,963 INFO  [main] org.example.Application: {"az.sdk.message":"hi there - global and log record context","foo":"bar","baz":42} 

// lazy context value - supplier will never be called if log level is too low
logger.atVerbose()
        .addKeyValue("foo", () -> "something expensive to calculate")
        .log("hi there - lazy value");
// 2022-02-23 16:04:02,964 DEBUG [main] org.example.Application: {"az.sdk.message":"hi there - lazy value","foo":"something expensive to calculate"} 

// pass strings and primitive types, otherwise toString will be (lazily) called
logger.atInfo()
        .addKeyValue("foo", complexObject)
        .log("hi there - lazy toString");
// 2022-02-23 16:04:02,966 INFO  [main] org.example.Application: {"az.sdk.message":"hi there - lazy toString","foo":"<ComplexType.toString()>"} 

// log exceptions with context
logger.atWarning()
        .addKeyValue("baz", 3.14)
        .log("something bad happened", ex);
// debug disabled: 2022-02-23 16:09:22,636 WARN  [main] org.example.Application: {"az.sdk.message":"something bad happened","exception":"'value' can't be null","foo":"bar"} 

throw logger.atError()
            .addKeyValue("foo", "bar")
            .log(new NullPointerException("'value' can't be null"));
//  debug disabled: 2022-02-23 16:08:15,422 ERROR [main] org.example.Application: {"az.sdk.message":"","exception":"'value' can't be null","baz":true} 

Similar to the non-contextual case, exception output depends on log level (stack trace and type info appear when debug level is enabled).

Logging and tracing

Logs can be automagically correlated to traces. E.g. if I add opentelemetry-extension-annotations and configure Application Insights agent, log record will appear under doSomething span.

@WithSpan
private static void doSomething(ClientLogger logger){
    // ...
    logger.info("hi there - should be correlated to trace");
}

If I configure opentelemtery-agent, I could also add ambient trace-id and span-id to my log records.

Query logs

Our logs are in JSON format, users of Azure Monitor can parse them at query time

traces 
| where message startswith "{\"az.sdk.message"
| project timestamp, logger=customDimensions["LoggerName"], level=customDimensions["LoggingLevel"], thread=customDimensions["ThreadName"], azSdkContext=parse_json(message)
| evaluate bag_unpack(azSdkContext)

• Splunk has similar capabilities.
• to parse and query stdout test logs, check out the tool prototype