diff --git a/sdk/core/azure-core/CHANGELOG.md b/sdk/core/azure-core/CHANGELOG.md index 87450c252b286..3f8beffbffebf 100644 --- a/sdk/core/azure-core/CHANGELOG.md +++ b/sdk/core/azure-core/CHANGELOG.md @@ -4,6 +4,8 @@ ### Features Added +- Added `ClientLogger` APIs (`atError`, `atWarning`, `atInfo`, `atVerbose`) that allow adding key-value pairs to log entries and `ClientLogger` constructor overloads that take context to apply to every log entry written with this logger instance. Logger writes entries that have context as JSON similar to `{"az.sdk.message":"on delivery","connectionId":"foo"}` + ### Breaking Changes ### Bugs Fixed diff --git a/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/ClientLogger.java b/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/ClientLogger.java index 0a414345f7061..3d39b40821ca5 100644 --- a/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/ClientLogger.java +++ b/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/ClientLogger.java @@ -10,6 +10,8 @@ import org.slf4j.LoggerFactory; import org.slf4j.helpers.NOPLogger; +import java.util.Collections; +import java.util.Map; import java.util.Objects; import java.util.function.Supplier; @@ -37,10 +39,14 @@ *
  • {@link ClientLogger#verbose(String, Object...) Verbose}
  • * * + *

    The logger is capable of producing json-formatted messages enriched with key value pairs. + * Context can be provided in the constructor and populated on every message or added per each log record.

    * @see Configuration */ public class ClientLogger { private final Logger logger; + private final String globalContextSerialized; + private final boolean hasGlobalContext; /** * Retrieves a logger for the passed class using the {@link LoggerFactory}. @@ -55,11 +61,47 @@ public ClientLogger(Class clazz) { * Retrieves a logger for the passed class name using the {@link LoggerFactory}. * * @param className Class name creating the logger. - * @throws RuntimeException it is an error. + * @throws RuntimeException when logging configuration is invalid depending on SLF4J implementation. */ public ClientLogger(String className) { + this(className, Collections.emptyMap()); + } + + /** + * Retrieves a logger for the passed class using the {@link LoggerFactory}. + * + * @param clazz Class creating the logger. + * @param context Context to be populated on every log record written with this logger. + * Objects are serialized with {@code toString()} method. + */ + public ClientLogger(Class clazz, Map context) { + this(clazz.getName(), context); + } + + /** + * Retrieves a logger for the passed class name using the {@link LoggerFactory} with + * context that will be populated on all log records produced with this logger. + * + * + *
    +     * Map<String, Object> context = new HashMap<>();
    +     * context.put("connectionId", "95a47cf");
    +     *
    +     * ClientLogger loggerWithContext = new ClientLogger(ClientLoggerJavaDocCodeSnippets.class, context);
    +     * loggerWithContext.info("A formattable message. Hello, {}", name);
    +     * 
    + * + * + * @param className Class name creating the logger. + * @param context Context to be populated on every log record written with this logger. + * Objects are serialized with {@code toString()} method. + * @throws RuntimeException when logging configuration is invalid depending on SLF4J implementation. + */ + public ClientLogger(String className, Map context) { Logger initLogger = LoggerFactory.getLogger(className); logger = initLogger instanceof NOPLogger ? new DefaultLogger(className) : initLogger; + globalContextSerialized = LoggingEventBuilder.writeJsonFragment(context); + hasGlobalContext = !CoreUtils.isNullOrEmpty(globalContextSerialized); } /** @@ -126,7 +168,11 @@ public void log(LogLevel logLevel, Supplier message, Throwable throwable */ public void verbose(String message) { if (logger.isDebugEnabled()) { - logger.debug(removeNewLinesFromLogMessage(message)); + if (hasGlobalContext) { + atVerbose().log(message); + } else { + logger.debug(removeNewLinesFromLogMessage(message)); + } } } @@ -170,7 +216,11 @@ public void verbose(String format, Object... args) { */ public void info(String message) { if (logger.isInfoEnabled()) { - logger.info(removeNewLinesFromLogMessage(message)); + if (hasGlobalContext) { + atInfo().log(message); + } else { + logger.info(removeNewLinesFromLogMessage(message)); + } } } @@ -215,7 +265,11 @@ public void info(String format, Object... args) { */ public void warning(String message) { if (logger.isWarnEnabled()) { - logger.warn(removeNewLinesFromLogMessage(message)); + if (hasGlobalContext) { + atWarning().log(message); + } else { + logger.warn(removeNewLinesFromLogMessage(message)); + } } } @@ -264,7 +318,11 @@ public void warning(String format, Object... args) { */ public void error(String message) { if (logger.isErrorEnabled()) { - logger.error(removeNewLinesFromLogMessage(message)); + if (hasGlobalContext) { + atError().log(message); + } else { + logger.error(removeNewLinesFromLogMessage(message)); + } } } @@ -392,12 +450,18 @@ public T logThrowableAsError(T throwable) { } /* - * Performs the logging. + * Performs the logging. Call only if logging at this level is enabled. * * @param format format-able message. * @param args Arguments for the message, if an exception is being logged last argument is the throwable. */ private void performLogging(LogLevel logLevel, boolean isExceptionLogging, String format, Object... args) { + if (hasGlobalContext) { + LoggingEventBuilder.create(logger, logLevel, globalContextSerialized, true) + .log(format, args); + return; + } + // If the logging level is less granular than verbose remove the potential throwable from the args. String throwableMessage = ""; if (doesArgsHaveThrowable(args)) { @@ -448,12 +512,21 @@ private void performLogging(LogLevel logLevel, boolean isExceptionLogging, Strin } /* - * Performs deferred logging. + * Performs deferred logging. Call only if logging at this level is enabled. * * @param logLevel sets the logging level * @param args Arguments for the message, if an exception is being logged last argument is the throwable. */ private void performDeferredLogging(LogLevel logLevel, Supplier messageSupplier, Throwable throwable) { + + if (hasGlobalContext) { + // LoggingEventBuilder writes log messages as json and performs all necessary escaping, i.e. no + // sanitization needed + LoggingEventBuilder.create(logger, logLevel, globalContextSerialized, true) + .log(messageSupplier, throwable); + return; + } + String message = removeNewLinesFromLogMessage(messageSupplier.get()); String throwableMessage = (throwable != null) ? throwable.getMessage() : ""; @@ -548,7 +621,7 @@ public boolean canLogAtLevel(LogLevel logLevel) { * @return instance of {@link LoggingEventBuilder} or no-op if error logging is disabled. */ public LoggingEventBuilder atError() { - return LoggingEventBuilder.create(logger, LogLevel.ERROR, canLogAtLevel(LogLevel.ERROR)); + return LoggingEventBuilder.create(logger, LogLevel.ERROR, globalContextSerialized, canLogAtLevel(LogLevel.ERROR)); } /** @@ -570,7 +643,7 @@ public LoggingEventBuilder atError() { * @return instance of {@link LoggingEventBuilder} or no-op if warn logging is disabled. */ public LoggingEventBuilder atWarning() { - return LoggingEventBuilder.create(logger, LogLevel.WARNING, canLogAtLevel(LogLevel.WARNING)); + return LoggingEventBuilder.create(logger, LogLevel.WARNING, globalContextSerialized, canLogAtLevel(LogLevel.WARNING)); } /** @@ -592,7 +665,7 @@ public LoggingEventBuilder atWarning() { * @return instance of {@link LoggingEventBuilder} or no-op if info logging is disabled. */ public LoggingEventBuilder atInfo() { - return LoggingEventBuilder.create(logger, LogLevel.INFORMATIONAL, canLogAtLevel(LogLevel.INFORMATIONAL)); + return LoggingEventBuilder.create(logger, LogLevel.INFORMATIONAL, globalContextSerialized, canLogAtLevel(LogLevel.INFORMATIONAL)); } /** @@ -613,6 +686,6 @@ public LoggingEventBuilder atInfo() { * @return instance of {@link LoggingEventBuilder} or no-op if verbose logging is disabled. */ public LoggingEventBuilder atVerbose() { - return LoggingEventBuilder.create(logger, LogLevel.VERBOSE, canLogAtLevel(LogLevel.VERBOSE)); + return LoggingEventBuilder.create(logger, LogLevel.VERBOSE, globalContextSerialized, canLogAtLevel(LogLevel.VERBOSE)); } } diff --git a/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/LoggingEventBuilder.java b/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/LoggingEventBuilder.java index 9e07d1f3a99ee..bb28f4823f8d5 100644 --- a/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/LoggingEventBuilder.java +++ b/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/LoggingEventBuilder.java @@ -4,13 +4,16 @@ package com.azure.core.util.logging; import com.azure.core.annotation.Fluent; +import com.azure.core.util.CoreUtils; import com.fasterxml.jackson.core.io.JsonStringEncoder; import org.slf4j.Logger; import org.slf4j.helpers.FormattingTuple; import org.slf4j.helpers.MessageFormatter; import java.util.ArrayList; +import java.util.Collections; import java.util.List; +import java.util.Map; import java.util.Objects; import java.util.function.Supplier; @@ -38,33 +41,37 @@ @Fluent public final class LoggingEventBuilder { private static final JsonStringEncoder JSON_STRING_ENCODER = JsonStringEncoder.getInstance(); - private static final LoggingEventBuilder NOOP = new LoggingEventBuilder(null, null, false); + private static final LoggingEventBuilder NOOP = new LoggingEventBuilder(null, null, null, false); private static final String AZURE_SDK_LOG_MESSAGE_KEY = "az.sdk.message"; private final Logger logger; private final LogLevel level; private List context; + private final String globalContextCached; + private final boolean hasGlobalContext; - // use flag instead for no-op instance instead of inheritance + // flag for no-op instance instead of inheritance private final boolean isEnabled; /** * Creates {@code LoggingEventBuilder} for provided level and {@link ClientLogger}. * If level is disabled, returns no-op instance. */ - static LoggingEventBuilder create(Logger logger, LogLevel level, boolean canLogAtLevel) { + static LoggingEventBuilder create(Logger logger, LogLevel level, String globalContextSerialized, boolean canLogAtLevel) { if (canLogAtLevel) { - return new LoggingEventBuilder(logger, level, true); + return new LoggingEventBuilder(logger, level, globalContextSerialized, true); } return NOOP; } - private LoggingEventBuilder(Logger logger, LogLevel level, boolean isEnabled) { + private LoggingEventBuilder(Logger logger, LogLevel level, String globalContextSerialized, boolean isEnabled) { this.logger = logger; this.level = level; this.isEnabled = isEnabled; - this.context = null; + this.context = Collections.emptyList(); + this.globalContextCached = globalContextSerialized == null ? "" : globalContextSerialized; + this.hasGlobalContext = !this.globalContextCached.isEmpty(); } /** @@ -94,6 +101,36 @@ public LoggingEventBuilder addKeyValue(String key, String value) { return this; } + /** + * Adds key with Object value to the context of current log being created. + * If logging is enabled at given level, and object is not null, uses {@code value.toString()} to + * serialize object. + * + *

    Code samples

    + * + *

    Adding string value to logging event context.

    + * + * + *
    +     * logger.atVerbose()
    +     *     // equivalent to addKeyValue("key", () -> new LoggableObject("string representation").toString()
    +     *     .addKeyValue("key", new LoggableObject("string representation"))
    +     *     .log("Param 1: {}, Param 2: {}, Param 3: {}", "param1", "param2", "param3");
    +     * 
    + * + * + * @param key String key. + * @param value Object value. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder addKeyValue(String key, Object value) { + if (this.isEnabled) { + addKeyValueInternal(key, value == null ? null : value.toString()); + } + + return this; + } + /** * Adds key with boolean value to the context of current log being created. * @@ -143,7 +180,7 @@ public LoggingEventBuilder addKeyValue(String key, long value) { */ public LoggingEventBuilder addKeyValue(String key, Supplier valueSupplier) { if (this.isEnabled) { - if (this.context == null) { + if (this.context.isEmpty()) { this.context = new ArrayList<>(); } @@ -175,6 +212,19 @@ public void log(Supplier messageSupplier) { } } + /** + * Logs message annotated with context. + * + * @param messageSupplier string message supplier. + * @param throwable {@link Throwable} for the message. + */ + public void log(Supplier messageSupplier, Throwable throwable) { + if (this.isEnabled) { + String message = messageSupplier != null ? messageSupplier.get() : null; + performLogging(level, message, throwable); + } + } + /** * Logs a format-able message that uses {@code {}} as the placeholder at {@code warning} log level. * @@ -205,14 +255,30 @@ public Throwable log(Throwable throwable) { return throwable; } + /** + * Logs the {@link RuntimeException} and returns it to be thrown. + * This API covers the cases where a checked exception type needs to be thrown and logged. + * + * @param runtimeException RuntimeException to be logged and returned. + * @return The passed {@link RuntimeException}. + * @throws NullPointerException If {@code runtimeException} is {@code null}. + */ + public RuntimeException log(RuntimeException runtimeException) { + Objects.requireNonNull(runtimeException, "'runtimeException' cannot be null."); + + if (this.isEnabled) { + performLogging(level, null, runtimeException); + } + + return runtimeException; + } + private String getMessageWithContext(String message, Throwable throwable) { if (message == null) { message = ""; } - int contextSize = context == null ? 0 : context.size(); - - StringBuilder sb = new StringBuilder(20 + contextSize * 20 + message.length()); + StringBuilder sb = new StringBuilder(20 + context.size() * 20 + message.length() + globalContextCached.length()); sb.append("{\"") // message must be first for log parsing tooling to work, key also works as a // marker for Azure SDK logs so we'll write it even if there is no message @@ -222,16 +288,25 @@ private String getMessageWithContext(String message, Throwable throwable) { sb.append("\""); if (throwable != null) { - sb.append(",\"exception\":\""); - JSON_STRING_ENCODER.quoteAsString(throwable.getMessage(), sb); - sb.append("\""); + sb.append(",\"exception\":"); + + String exceptionMessage = throwable.getMessage(); + if (exceptionMessage != null) { + sb.append("\""); + JSON_STRING_ENCODER.quoteAsString(exceptionMessage, sb); + sb.append("\""); + } else { + sb.append("null"); + } } - if (context != null) { - for (int i = 0; i < context.size(); i++) { - context.get(i) - .writeKeyAndValue(sb.append(",")); - } + if (hasGlobalContext) { + sb.append(",").append(globalContextCached); + } + + for (int i = 0; i < context.size(); i++) { + context.get(i) + .write(sb.append(",")); } sb.append("}"); @@ -239,7 +314,7 @@ private String getMessageWithContext(String message, Throwable throwable) { } private void addKeyValueInternal(String key, Object value) { - if (this.context == null) { + if (this.context.isEmpty()) { this.context = new ArrayList<>(); } @@ -252,7 +327,7 @@ private void addKeyValueInternal(String key, Object value) { * @param format format-able message. * @param args Arguments for the message, if an exception is being logged last argument is the throwable. */ - void performLogging(LogLevel logLevel, String format, Object... args) { + private void performLogging(LogLevel logLevel, String format, Object... args) { Throwable throwable = null; if (doesArgsHaveThrowable(args)) { @@ -295,8 +370,70 @@ void performLogging(LogLevel logLevel, String format, Object... args) { } /** - * Key value pair with basic serialization capabilities. + * Serializes passed map to string containing valid JSON fragment: + * e.g. "k1":"v1","k2":"v2", properly escaped and without trailing comma. + * + * For complex object serialization, it calls {@code toString()} guarded with null check. + * + * @param context to serialize. + * + * @returns Serialized JSON fragment or an empty string. */ + static String writeJsonFragment(Map context) { + if (CoreUtils.isNullOrEmpty(context)) { + return ""; + } + + StringBuilder formatter = new StringBuilder(context.size() * 20); + for (Map.Entry pair : context.entrySet()) { + writeKeyAndValue(pair.getKey(), pair.getValue(), formatter).append(","); + } + + // remove trailing comma just in case + return formatter.deleteCharAt(formatter.length() - 1) + .toString(); + } + + private static StringBuilder writeKeyAndValue(String key, Object value, StringBuilder formatter) { + formatter.append("\""); + JSON_STRING_ENCODER.quoteAsString(key, formatter); + formatter.append("\":"); + + if (value == null) { + return formatter.append("null"); + } + + if (isPrimitive(value)) { + JSON_STRING_ENCODER.quoteAsString(value.toString(), formatter); + return formatter; + } + + formatter.append("\""); + JSON_STRING_ENCODER.quoteAsString(value.toString(), formatter); + return formatter.append("\""); + } + + /** + * Returns true if the value is an instance of a primitive type and false otherwise. + */ + private static boolean isPrimitive(Object value) { + // most of the time values are strings + if (value instanceof String) { + return false; + } + + if (value instanceof Boolean + || value instanceof Integer + || value instanceof Long + || value instanceof Byte + || value instanceof Double + || value instanceof Float) { + return true; + } + + return false; + } + private static final class ContextKeyValuePair { private final String key; private final Object value; @@ -317,32 +454,12 @@ private static final class ContextKeyValuePair { /** * Writes "key":"value" json string to provided StringBuilder. */ - public StringBuilder writeKeyAndValue(StringBuilder formatter) { - formatter.append("\""); - JSON_STRING_ENCODER.quoteAsString(key, formatter); - formatter.append("\":"); - - String valueStr = null; - if (value != null) { - // LoggingEventBuilder only supports primitives and strings - if (!(value instanceof String)) { - JSON_STRING_ENCODER.quoteAsString(value.toString(), formatter); - return formatter; - } - - valueStr = (String) value; - } else if (valueSupplier != null) { - valueStr = valueSupplier.get(); - } - - if (valueStr == null) { - return formatter.append("null"); + public StringBuilder write(StringBuilder formatter) { + if (valueSupplier == null) { + return writeKeyAndValue(key, value, formatter); } - formatter.append("\""); - JSON_STRING_ENCODER.quoteAsString(valueStr, formatter); - - return formatter.append("\""); + return writeKeyAndValue(key, valueSupplier.get(), formatter); } } } diff --git a/sdk/core/azure-core/src/samples/java/com/azure/core/util/logging/ClientLoggerJavaDocCodeSnippets.java b/sdk/core/azure-core/src/samples/java/com/azure/core/util/logging/ClientLoggerJavaDocCodeSnippets.java index bc26b1ef2fb6f..fb9c8d7985e1d 100644 --- a/sdk/core/azure-core/src/samples/java/com/azure/core/util/logging/ClientLoggerJavaDocCodeSnippets.java +++ b/sdk/core/azure-core/src/samples/java/com/azure/core/util/logging/ClientLoggerJavaDocCodeSnippets.java @@ -5,6 +5,8 @@ import java.io.File; import java.io.IOException; +import java.util.HashMap; +import java.util.Map; /** * Code snippets for {@link ClientLogger} javadocs @@ -74,6 +76,14 @@ public void loggingSnippets() { } // END: com.azure.core.util.logging.clientlogger.error#string-object + // BEGIN: com.azure.core.util.logging.clientlogger#globalcontext + Map context = new HashMap<>(); + context.put("connectionId", "95a47cf"); + + ClientLogger loggerWithContext = new ClientLogger(ClientLoggerJavaDocCodeSnippets.class, context); + loggerWithContext.info("A formattable message. Hello, {}", name); + // END: com.azure.core.util.logging.clientlogger#globalcontext + // BEGIN: com.azure.core.util.logging.clientlogger.atInfo logger.atInfo() .addKeyValue("key", "value") @@ -109,6 +119,13 @@ public void loggingSnippets() { .addKeyValue("key3", () -> getName()) .log("A formattable message. Hello, {}", name); // END: com.azure.core.util.logging.loggingeventbuilder + + // BEGIN: com.azure.core.util.logging.clientlogger.atverbose.addKeyValue#object + logger.atVerbose() + // equivalent to addKeyValue("key", () -> new LoggableObject("string representation").toString() + .addKeyValue("key", new LoggableObject("string representation")) + .log("Param 1: {}, Param 2: {}, Param 3: {}", "param1", "param2", "param3"); + // END: com.azure.core.util.logging.clientlogger.atverbose.addKeyValue#object } /** @@ -138,4 +155,16 @@ private String getName() { private void upload(File resource) throws IOException { throw new IOException(); } + + class LoggableObject { + private final String str; + LoggableObject(String str) { + this.str = str; + } + + @Override + public String toString() { + return str; + } + } } diff --git a/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/ClientLoggerTests.java b/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/ClientLoggerTests.java index 377ef44267c77..0783728a198f1 100644 --- a/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/ClientLoggerTests.java +++ b/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/ClientLoggerTests.java @@ -27,6 +27,9 @@ import java.io.UncheckedIOException; import java.io.UnsupportedEncodingException; import java.nio.charset.StandardCharsets; +import java.util.Collections; +import java.util.LinkedHashMap; +import java.util.Map; import java.util.function.Consumer; import java.util.function.Supplier; import java.util.stream.Stream; @@ -48,6 +51,7 @@ public class ClientLoggerTests { private String originalLogLevel; private PrintStream originalSystemOut; private ByteArrayOutputStream logCaptureStream; + private Map globalContext; @BeforeEach public void setupLoggingConfiguration() { @@ -58,6 +62,12 @@ public void setupLoggingConfiguration() { originalSystemOut = System.out; logCaptureStream = new ByteArrayOutputStream(); System.setOut(new PrintStream(logCaptureStream)); + + // preserve order + globalContext = new LinkedHashMap<>(); + globalContext.put("connectionId", "foo"); + globalContext.put("linkName", 1); + globalContext.put("anotherKey", new LoggableObject("hello world")); } @AfterEach @@ -353,6 +363,153 @@ public void logWithContext(LogLevel logLevelToConfigure) { LogLevel.WARNING); } + /** + * Tests that logging with context of string message writes + * log message and global context in correct format and depending on the level. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithGlobalContext(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalContext); + logger.warning("Param 1: {}, Param 2: {}, Param 3: {}", "test1", "test2", "test3"); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + + /** + * Tests that logging with context of string message writes + * log message and global context in correct format at info level + */ + @Test + public void logInfoWithGlobalContext() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalContext); + logger.info("message"); + + assertMessage( + "{\"az.sdk.message\":\"message\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.VERBOSE); + } + + /** + * Tests that logging with context of string message writes + * log message and global context in correct format at verbose level + */ + @Test + public void logVerboseWithGlobalContext() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalContext); + logger.verbose("message"); + + assertMessage( + "{\"az.sdk.message\":\"message\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.INFORMATIONAL); + } + + /** + * Tests that logging with context of string message writes + * log message and global context in correct format at warning level + */ + @Test + public void logWarningWithGlobalContext() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + + new ClientLogger(ClientLoggerTests.class, globalContext) + .warning("message"); + + assertMessage( + "{\"az.sdk.message\":\"message\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.WARNING); + } + + /** + * Tests that logging with context of string message writes + * log message and global context in correct format at error level + */ + @Test + public void logErrorWithGlobalContext() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + + new ClientLogger(ClientLoggerTests.class, globalContext) + .error("message"); + + assertMessage( + "{\"az.sdk.message\":\"message\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.ERROR); + } + + /** + * Tests empty global context + */ + @Test + public void logWithEmptyGlobalContext() { + setupLogLevel(LogLevel.INFORMATIONAL.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, Collections.emptyMap()); + logger.warning("Param 1: {}, Param 2: {}, Param 3: {}", "test1", "test2", "test3"); + + assertMessage( + "Param 1: test1, Param 2: test2, Param 3: test3", + byteArraySteamToString(logCaptureStream), + LogLevel.INFORMATIONAL, + LogLevel.WARNING); + } + + /** + * Tests null global context + */ + @Test + public void logWithNullGlobalContext() { + setupLogLevel(LogLevel.INFORMATIONAL.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, null); + logger.info("Param 1: {}, Param 2: {}, Param 3: {}", "test1", "test2", "test3"); + + assertMessage( + "Param 1: test1, Param 2: test2, Param 3: test3", + byteArraySteamToString(logCaptureStream), + LogLevel.INFORMATIONAL, + LogLevel.INFORMATIONAL); + } + + /** + * Tests that logging with context of string message writes + * log message and local and globacl context in correct format and depending on the level. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithGlobalAndLocalContext(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalContext); + logger.atInfo() + .addKeyValue("local", true) + .addKeyValue("connectionId", "conflict") + .log("Param 1: {}, Param 2: {}, Param 3: {}", "test1", "test2", "test3"); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\",\"local\":true,\"connectionId\":\"conflict\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.INFORMATIONAL); + } + /** * Tests that contextual logging without context of string message writes * log message and context in correct format and depending on the level. @@ -363,9 +520,7 @@ public void contextualLogWithoutContext(LogLevel logLevelToConfigure) { setupLogLevel(logLevelToConfigure.getLogLevel()); ClientLogger logger = new ClientLogger(ClientLoggerTests.class); - String message = String.format("Param 1: %s, Param 2: %s, Param 3: %s", "test1", "test2", "test3"); - - logger.atWarning().log(message); + logger.atWarning().log(String.format("Param 1: %s, Param 2: %s, Param 3: %s", "test1", "test2", "test3")); assertMessage( "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\"}", @@ -373,6 +528,26 @@ public void contextualLogWithoutContext(LogLevel logLevelToConfigure) { logLevelToConfigure, LogLevel.WARNING); } + + + /** + * Tests message supplier with local and global context. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithGlobalContextMessageSupplier(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalContext); + + logger.log(LogLevel.INFORMATIONAL, () -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "test1", "test2", "test3")); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":\"foo\",\"linkName\":1,\"anotherKey\":\"hello world\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.INFORMATIONAL); + } + /** * Tests message supplier with context. */ @@ -417,7 +592,7 @@ public void logWithContextNullMessage() { } /** - * Tests that newline is escaped in message, keys and values. + * Tests that newline is escaped in message, keys and values. */ @Test public void logWithContextNewLineIsEscaped() { @@ -438,6 +613,29 @@ public void logWithContextNewLineIsEscaped() { LogLevel.INFORMATIONAL); } + /** + * Tests that global context is escaped + */ + @Test + public void logWithGlobalContextIsEscaped() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + + // preserve order + Map globalCtx = new LinkedHashMap<>(); + globalCtx.put("link\tName", 1); + globalCtx.put("another\rKey\n", new LoggableObject("hello \"world\"\r\n")); + + ClientLogger logger = new ClientLogger(ClientLoggerTests.class, globalCtx); + + logger.verbose("\"message\""); + + assertMessage( + "{\"az.sdk.message\":\"\\\"message\\\"\",\"link\\tName\":1,\"another\\rKey\\n\":\"hello \\\"world\\\"\\r\\n\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.INFORMATIONAL); + } + /** * Tests that logging with context with null message supplier does not throw. */ @@ -481,6 +679,25 @@ public void logWithContextValueSupplier() { LogLevel.WARNING); } + /** + * Tests supplied context value. + */ + @Test + public void logWithContextObject() { + setupLogLevel(LogLevel.INFORMATIONAL.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + logger.atWarning() + .addKeyValue("linkName", new LoggableObject("some complex object")) + .log("test"); + + assertMessage( + "{\"az.sdk.message\":\"test\",\"linkName\":\"some complex object\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.INFORMATIONAL, + LogLevel.WARNING); + } + /** * Tests message with args and context. */ @@ -531,6 +748,35 @@ public void logWithContextWithThrowableInArgs(LogLevel logLevelToConfigure) { LogLevel.WARNING); } + /** + * Tests logging with context and supplied message when args have throwable (stack trace is only logged at debug) + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextMessageSupplierAndThrowableInArgs(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + String exceptionMessage = "An exception message"; + IOException ioException = createIOException(exceptionMessage); + + logger.atWarning() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", "bar") + .log(() -> String.format("hello %s", "world"), ioException); + + String message = "{\"az.sdk.message\":\"hello world\",\"exception\":\"" + exceptionMessage + "\",\"connectionId\":\"foo\",\"linkName\":\"bar\"}"; + if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { + message += System.lineSeparator() + ioException.toString() + System.lineSeparator() + "\tat " + ioException.getStackTrace()[0].toString(); + } + + assertMessage( + message, + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + /** * Tests json escape in keys, values, message and exception message */ @@ -568,7 +814,7 @@ public void logWithContextWithThrowableInArgsAndEscaping(LogLevel logLevelToConf */ @ParameterizedTest @MethodSource("provideLogLevels") - public void logWithContextWithThrowableInCause(LogLevel logLevelToConfigure) { + public void logWithContextRuntimeException(LogLevel logLevelToConfigure) { setupLogLevel(logLevelToConfigure.getLogLevel()); ClientLogger logger = new ClientLogger(ClientLoggerTests.class); @@ -592,6 +838,35 @@ public void logWithContextWithThrowableInCause(LogLevel logLevelToConfigure) { LogLevel.WARNING); } + /** + * Tests logging with context when cause is set + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextThrowable(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + String exceptionMessage = "An exception message"; + IOException ioException = createIOException(exceptionMessage); + + assertSame(ioException, logger.atWarning() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", "bar") + .log(ioException)); + + String message = "{\"az.sdk.message\":\"\",\"exception\":\"" + exceptionMessage + "\",\"connectionId\":\"foo\",\"linkName\":\"bar\"}"; + if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { + message += System.lineSeparator() + ioException.toString() + System.lineSeparator() + "\tat " + ioException.getStackTrace()[0].toString(); + } + + assertMessage( + message, + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + @Test public void testIsSupplierLoggingWithException() { Supplier supplier = () -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "test1", "test2", "test3"); @@ -992,4 +1267,16 @@ private static Stream validLogLevelSupplier() { Arguments.of(null, LogLevel.NOT_SET) ); } + + class LoggableObject { + private final String str; + LoggableObject(String str) { + this.str = str; + } + + @Override + public String toString() { + return str; + } + } }