diff --git a/eng/code-quality-reports/src/main/resources/checkstyle/checkstyle-suppressions.xml b/eng/code-quality-reports/src/main/resources/checkstyle/checkstyle-suppressions.xml index 987f0e39fe54b..1bd220ae71f70 100755 --- a/eng/code-quality-reports/src/main/resources/checkstyle/checkstyle-suppressions.xml +++ b/eng/code-quality-reports/src/main/resources/checkstyle/checkstyle-suppressions.xml @@ -242,7 +242,8 @@ the main ServiceBusClientBuilder. --> - + + diff --git a/eng/code-quality-reports/src/main/resources/spotbugs/spotbugs-exclude.xml b/eng/code-quality-reports/src/main/resources/spotbugs/spotbugs-exclude.xml index 83c727d748993..0f2bdff00192a 100755 --- a/eng/code-quality-reports/src/main/resources/spotbugs/spotbugs-exclude.xml +++ b/eng/code-quality-reports/src/main/resources/spotbugs/spotbugs-exclude.xml @@ -2404,6 +2404,10 @@ + + + + diff --git a/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/LoggingUtils.java b/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/LoggingUtils.java index a847551c2c7f5..033ca659de612 100644 --- a/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/LoggingUtils.java +++ b/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/LoggingUtils.java @@ -5,13 +5,15 @@ import com.azure.core.util.CoreUtils; +import java.util.Arrays; + /** * Contains utility methods for logging. */ public final class LoggingUtils { private static final char CR = '\r'; private static final char LF = '\n'; - + private LoggingUtils() { } @@ -48,4 +50,29 @@ public static String removeNewLinesFromLogMessage(String logMessage) { sb.append(logMessage, prevStart, logMessage.length()); return sb.toString(); } + + /* + * Determines if the arguments contains a throwable that would be logged, SLF4J logs a throwable if it is the last + * element in the argument list. + * + * @param args The arguments passed to format the log message. + * @return True if the last element is a throwable, false otherwise. + */ + public static boolean doesArgsHaveThrowable(Object... args) { + if (args.length == 0) { + return false; + } + + return args[args.length - 1] instanceof Throwable; + } + + /* + * Removes the last element from the arguments as it is a throwable. + * + * @param args The arguments passed to format the log message. + * @return The arguments with the last element removed. + */ + public static Object[] removeThrowable(Object... args) { + return Arrays.copyOf(args, args.length - 1); + } } 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 d4bbfd44f4164..0a414345f7061 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,12 +10,14 @@ import org.slf4j.LoggerFactory; import org.slf4j.helpers.NOPLogger; -import java.util.Arrays; import java.util.Objects; import java.util.function.Supplier; import static com.azure.core.implementation.logging.LoggingUtils.removeNewLinesFromLogMessage; +import static com.azure.core.implementation.logging.LoggingUtils.doesArgsHaveThrowable; +import static com.azure.core.implementation.logging.LoggingUtils.removeThrowable; + /** * This is a fluent logger helper class that wraps a pluggable {@link Logger}. * @@ -345,11 +347,10 @@ public T logThowableAsWarning(T throwable) { */ public T logThrowableAsWarning(T throwable) { Objects.requireNonNull(throwable, "'throwable' cannot be null."); - if (!logger.isWarnEnabled()) { - return throwable; + if (logger.isWarnEnabled()) { + performLogging(LogLevel.WARNING, true, throwable.getMessage(), throwable); } - performLogging(LogLevel.WARNING, true, throwable.getMessage(), throwable); return throwable; } @@ -453,9 +454,9 @@ private void performLogging(LogLevel logLevel, boolean isExceptionLogging, Strin * @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) { + String message = removeNewLinesFromLogMessage(messageSupplier.get()); String throwableMessage = (throwable != null) ? throwable.getMessage() : ""; - String message = messageSupplier.get(); - message = removeNewLinesFromLogMessage(message); + switch (logLevel) { case VERBOSE: if (throwable != null) { @@ -489,7 +490,6 @@ private void performDeferredLogging(LogLevel logLevel, Supplier messageS * @param args The arguments passed to evaluate suppliers in args. * @return Return the argument with evaluated supplier */ - Object[] evaluateSupplierArgument(Object[] args) { if (isSupplierLogging(args)) { args[0] = ((Supplier) args[0]).get(); @@ -530,28 +530,89 @@ public boolean canLogAtLevel(LogLevel logLevel) { } } - /* - * Determines if the arguments contains a throwable that would be logged, SLF4J logs a throwable if it is the last - * element in the argument list. + /** + * Creates {@link LoggingEventBuilder} for {@code error} log level that can be + * used to enrich log with additional context. + *

Code samples

+ * + *

Logging with context at error level.

* - * @param args The arguments passed to format the log message. - * @return True if the last element is a throwable, false otherwise. + * + *
+     * logger.atVerbose()
+     *     .addKeyValue("key", 1L)
+     *     .log(() -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "param1", "param2", "param3"));
+     * 
+ * + * + * @return instance of {@link LoggingEventBuilder} or no-op if error logging is disabled. */ - private boolean doesArgsHaveThrowable(Object... args) { - if (args.length == 0) { - return false; - } + public LoggingEventBuilder atError() { + return LoggingEventBuilder.create(logger, LogLevel.ERROR, canLogAtLevel(LogLevel.ERROR)); + } + + /** + * Creates {@link LoggingEventBuilder} for {@code warning} log level that can be + * used to enrich log with additional context. + + *

Code samples

+ * + *

Logging with context at warning level.

+ * + * + *
+     * logger.atWarning()
+     *     .addKeyValue("key", "value")
+     *     .log("A formattable message. Hello, {}", name, exception);
+     * 
+ * + * + * @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 args[args.length - 1] instanceof Throwable; + /** + * Creates {@link LoggingEventBuilder} for {@code info} log level that can be + * used to enrich log with additional context. + * + *

Code samples

+ * + *

Logging with context at info level.

+ * + * + *
+     * logger.atInfo()
+     *     .addKeyValue("key", "value")
+     *     .log("A formattable message. Hello, {}", name);
+     * 
+ * + * + * @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)); } - /* - * Removes the last element from the arguments as it is a throwable. + /** + * Creates {@link LoggingEventBuilder} for {@code verbose} log level that can be + * used to enrich log with additional context. + *

Code samples

+ * + *

Logging with context at verbose level.

+ * + * + *
+     * logger.atVerbose()
+     *     .addKeyValue("key", 1L)
+     *     .log(() -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "param1", "param2", "param3"));
+     * 
+ * * - * @param args The arguments passed to format the log message. - * @return The arguments with the last element removed. + * @return instance of {@link LoggingEventBuilder} or no-op if verbose logging is disabled. */ - private Object[] removeThrowable(Object... args) { - return Arrays.copyOf(args, args.length - 1); + public LoggingEventBuilder atVerbose() { + return LoggingEventBuilder.create(logger, LogLevel.VERBOSE, 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 new file mode 100644 index 0000000000000..9e07d1f3a99ee --- /dev/null +++ b/sdk/core/azure-core/src/main/java/com/azure/core/util/logging/LoggingEventBuilder.java @@ -0,0 +1,348 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package com.azure.core.util.logging; + +import com.azure.core.annotation.Fluent; +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.List; +import java.util.Objects; +import java.util.function.Supplier; + +import static com.azure.core.implementation.logging.LoggingUtils.doesArgsHaveThrowable; +import static com.azure.core.implementation.logging.LoggingUtils.removeThrowable; + +/** + * This class provides fluent API to write logs using {@link ClientLogger} and + * enrich them with additional context. + * + *

Code samples

+ * + *

Logging event with context.

+ * + * + *
+ * logger.atInfo()
+ *     .addKeyValue("key1", "value1")
+ *     .addKeyValue("key2", true)
+ *     .addKeyValue("key3", () -> getName())
+ *     .log("A formattable message. Hello, {}", name);
+ * 
+ * + */ +@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 String AZURE_SDK_LOG_MESSAGE_KEY = "az.sdk.message"; + + private final Logger logger; + private final LogLevel level; + private List context; + + // use flag instead 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) { + if (canLogAtLevel) { + return new LoggingEventBuilder(logger, level, true); + } + + return NOOP; + } + + private LoggingEventBuilder(Logger logger, LogLevel level, boolean isEnabled) { + this.logger = logger; + this.level = level; + this.isEnabled = isEnabled; + this.context = null; + } + + /** + * Adds key with String value pair to the context of current log being created. + * + *

Code samples

+ * + *

Adding string value to logging event context.

+ * + * + *
+     * logger.atInfo()
+     *     .addKeyValue("key", "value")
+     *     .log("A formattable message. Hello, {}", name);
+     * 
+ * + * + * @param key String key. + * @param value String value. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder addKeyValue(String key, String value) { + if (this.isEnabled) { + addKeyValueInternal(key, value); + } + + return this; + } + + /** + * Adds key with boolean value to the context of current log being created. + * + * @param key String key. + * @param value boolean value. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder addKeyValue(String key, boolean value) { + if (this.isEnabled) { + addKeyValueInternal(key, value); + } + return this; + } + + /** + * Adds key with long value to the context of current log event being created. + * + *

Code samples

+ * + *

Adding an integer value to logging event context.

+ * + * + *
+     * logger.atVerbose()
+     *     .addKeyValue("key", 1L)
+     *     .log(() -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "param1", "param2", "param3"));
+     * 
+ * + * + * @param key String key. + * @param value long value. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder addKeyValue(String key, long value) { + if (this.isEnabled) { + addKeyValueInternal(key, value); + } + return this; + } + + /** + * Adds key with String value supplier to the context of current log event being created. + * + * @param key String key. + * @param valueSupplier String value supplier function. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder addKeyValue(String key, Supplier valueSupplier) { + if (this.isEnabled) { + if (this.context == null) { + this.context = new ArrayList<>(); + } + + this.context.add(new ContextKeyValuePair(key, valueSupplier)); + } + return this; + } + + /** + * Logs message annotated with context. + * + * @param message the message to log. + */ + public void log(String message) { + if (this.isEnabled) { + performLogging(level, message); + } + } + + /** + * Logs message annotated with context. + * + * @param messageSupplier string message supplier. + */ + public void log(Supplier messageSupplier) { + if (this.isEnabled) { + String message = messageSupplier != null ? messageSupplier.get() : null; + performLogging(level, message); + } + } + + /** + * Logs a format-able message that uses {@code {}} as the placeholder at {@code warning} log level. + * + * @param format The format-able message to log. + * @param args Arguments for the message. If an exception is being logged, the last argument should be the {@link + * Throwable}. + */ + public void log(String format, Object... args) { + if (this.isEnabled) { + performLogging(level, format, args); + } + } + + /** + * Logs the {@link Throwable} and returns it to be thrown. + * + * @param throwable Throwable to be logged and returned. + * @return The passed {@link Throwable}. + * @throws NullPointerException If {@code throwable} is {@code null}. + */ + public Throwable log(Throwable throwable) { + Objects.requireNonNull(throwable, "'throwable' cannot be null."); + + if (this.isEnabled) { + performLogging(level, null, throwable); + } + + return throwable; + } + + 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()); + 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 + .append(AZURE_SDK_LOG_MESSAGE_KEY) + .append("\":\""); + JSON_STRING_ENCODER.quoteAsString(message, sb); + sb.append("\""); + + if (throwable != null) { + sb.append(",\"exception\":\""); + JSON_STRING_ENCODER.quoteAsString(throwable.getMessage(), sb); + sb.append("\""); + } + + if (context != null) { + for (int i = 0; i < context.size(); i++) { + context.get(i) + .writeKeyAndValue(sb.append(",")); + } + } + + sb.append("}"); + return sb.toString(); + } + + private void addKeyValueInternal(String key, Object value) { + if (this.context == null) { + this.context = new ArrayList<>(); + } + + this.context.add(new ContextKeyValuePair(key, value)); + } + + /* + * Performs the logging. + * + * @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) { + + Throwable throwable = null; + if (doesArgsHaveThrowable(args)) { + Object throwableObj = args[args.length - 1]; + + // This is true from before but is needed to appease SpotBugs. + if (throwableObj instanceof Throwable) { + throwable = (Throwable) throwableObj; + } + + /* + * Environment is logging at a level higher than verbose, strip out the throwable as it would log its + * stack trace which is only expected when logging at a verbose level. + */ + if (!logger.isDebugEnabled()) { + args = removeThrowable(args); + } + } + + FormattingTuple tuple = MessageFormatter.arrayFormat(format, args); + String message = getMessageWithContext(tuple.getMessage(), throwable); + + switch (logLevel) { + case VERBOSE: + logger.debug(message, tuple.getThrowable()); + break; + case INFORMATIONAL: + logger.info(message, tuple.getThrowable()); + break; + case WARNING: + logger.warn(message, tuple.getThrowable()); + break; + case ERROR: + logger.error(message, tuple.getThrowable()); + break; + default: + // Don't do anything, this state shouldn't be possible. + break; + } + } + + /** + * Key value pair with basic serialization capabilities. + */ + private static final class ContextKeyValuePair { + private final String key; + private final Object value; + private final Supplier valueSupplier; + + ContextKeyValuePair(String key, Object value) { + this.key = key; + this.value = value; + this.valueSupplier = null; + } + + ContextKeyValuePair(String key, Supplier valueSupplier) { + this.key = key; + this.value = null; + this.valueSupplier = valueSupplier; + } + + /** + * 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"); + } + + formatter.append("\""); + JSON_STRING_ENCODER.quoteAsString(valueStr, formatter); + + return formatter.append("\""); + } + } +} 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 5b40dea396875..bc26b1ef2fb6f 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 @@ -73,6 +73,42 @@ public void loggingSnippets() { logger.error("A formattable message. Hello, {}", name, ex); } // END: com.azure.core.util.logging.clientlogger.error#string-object + + // BEGIN: com.azure.core.util.logging.clientlogger.atInfo + logger.atInfo() + .addKeyValue("key", "value") + .log("A formattable message. Hello, {}", name); + // END: com.azure.core.util.logging.clientlogger.atInfo + + // BEGIN: com.azure.core.util.logging.clientlogger.atWarning + logger.atWarning() + .addKeyValue("key", "value") + .log("A formattable message. Hello, {}", name, exception); + // END: com.azure.core.util.logging.clientlogger.atWarning + + // BEGIN: com.azure.core.util.logging.clientlogger.atError#deffered-value + try { + upload(resource); + } catch (IOException ex) { + logger.atError() + .addKeyValue("key", () -> "Expensive to calculate value") + .log("A formattable message. Hello, {}", name, ex); + } + // END: com.azure.core.util.logging.clientlogger.atError#deffered-value + + // BEGIN: com.azure.core.util.logging.clientlogger.atverbose.addKeyValue#primitive + logger.atVerbose() + .addKeyValue("key", 1L) + .log(() -> String.format("Param 1: %s, Param 2: %s, Param 3: %s", "param1", "param2", "param3")); + // END: com.azure.core.util.logging.clientlogger.atverbose.addKeyValue#primitive + + // BEGIN: com.azure.core.util.logging.loggingeventbuilder + logger.atInfo() + .addKeyValue("key1", "value1") + .addKeyValue("key2", true) + .addKeyValue("key3", () -> getName()) + .log("A formattable message. Hello, {}", name); + // END: com.azure.core.util.logging.loggingeventbuilder } /** 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 efd4b65a29624..377ef44267c77 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 @@ -5,6 +5,7 @@ import com.azure.core.util.Configuration; import com.azure.core.util.CoreUtils; +import com.fasterxml.jackson.core.io.JsonStringEncoder; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; @@ -33,6 +34,7 @@ import static com.azure.core.util.Configuration.PROPERTY_AZURE_LOG_LEVEL; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertSame; import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; @@ -327,6 +329,269 @@ public void testIsSupplierLogging() { assertTrue(logger.isSupplierLogging(args)); } + /** + * Tests that logging with context of string message writes + * log message and context in correct format and depending on the level. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContext(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() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", 1) + .log(message); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":\"foo\",\"linkName\":1}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + + /** + * Tests that contextual logging without context of string message writes + * log message and context in correct format and depending on the level. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + 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); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + /** + * Tests message supplier with context. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextMessageSupplier(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.atInfo() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", "bar") + .log(() -> message); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":\"foo\",\"linkName\":\"bar\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.INFORMATIONAL); + } + + /** + * Tests that logging with context with null message does not throw. + */ + @Test + public void logWithContextNullMessage() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + logger.atVerbose() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", true) + .log((String) null); + + assertMessage( + "{\"az.sdk.message\":\"\",\"connectionId\":\"foo\",\"linkName\":true}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.INFORMATIONAL); + } + + /** + * Tests that newline is escaped in message, keys and values. + */ + @Test + public void logWithContextNewLineIsEscaped() { + setupLogLevel(LogLevel.VERBOSE.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + logger.atVerbose() + .addKeyValue("connection\nId" + System.lineSeparator(), "foo") + .addKeyValue("link\r\nName", "test" + System.lineSeparator() + "me") + .log("multiline " + System.lineSeparator() + "message"); + + String escapedNewLine = new String(JsonStringEncoder.getInstance().quoteAsString(System.lineSeparator())); + + assertMessage( + "{\"az.sdk.message\":\"multiline " + escapedNewLine + "message\",\"connection\\nId" + escapedNewLine + "\":\"foo\",\"link\\r\\nName\":\"test" + escapedNewLine + "me\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.VERBOSE, + LogLevel.INFORMATIONAL); + } + + /** + * Tests that logging with context with null message supplier does not throw. + */ + @Test + public void logWithContextNullSupplier() { + setupLogLevel(LogLevel.INFORMATIONAL.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + Supplier message = null; + + logger.atError() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", (String) null) + .log(message); + + assertMessage( + "{\"az.sdk.message\":\"\",\"connectionId\":\"foo\",\"linkName\":null}", + byteArraySteamToString(logCaptureStream), + LogLevel.INFORMATIONAL, + LogLevel.ERROR); + } + + /** + * Tests supplied context value. + */ + @Test + public void logWithContextValueSupplier() { + setupLogLevel(LogLevel.INFORMATIONAL.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + logger.atWarning() + // this is technically invalid, but we should not throw because of logging in runtime + .addKeyValue("connectionId", (Supplier) null) + .addKeyValue("linkName", () -> String.format("complex value %s", 123)) + .log("test"); + + assertMessage( + "{\"az.sdk.message\":\"test\",\"connectionId\":null,\"linkName\":\"complex value 123\"}", + byteArraySteamToString(logCaptureStream), + LogLevel.INFORMATIONAL, + LogLevel.WARNING); + } + + /** + * Tests message with args and context. + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logMessageAndArgsWithContext(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + logger.atWarning() + .addKeyValue("connectionId", () -> null) + .addKeyValue("linkName", "bar") + .log("Param 1: {}, Param 2: {}, Param 3: {}", "test1", "test2", "test3"); + + assertMessage( + "{\"az.sdk.message\":\"Param 1: test1, Param 2: test2, Param 3: test3\",\"connectionId\":null,\"linkName\":\"bar\"}", + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + + /** + * Tests logging with context when args have throwable (stack trace is only logged at debug) + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextWithThrowableInArgs(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + String exceptionMessage = "An exception message"; + RuntimeException runtimeException = createIllegalStateException(exceptionMessage); + + logger.atWarning() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", "bar") + .log("hello {}", "world", runtimeException); + + String message = "{\"az.sdk.message\":\"hello world\",\"exception\":\"" + exceptionMessage + "\",\"connectionId\":\"foo\",\"linkName\":\"bar\"}"; + if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { + message += System.lineSeparator() + runtimeException.toString() + System.lineSeparator() + "\tat " + runtimeException.getStackTrace()[0].toString(); + } + + assertMessage( + message, + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + + /** + * Tests json escape in keys, values, message and exception message + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextWithThrowableInArgsAndEscaping(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + String exceptionMessage = "An exception \tmessage with \"special characters\"\r\n"; + RuntimeException runtimeException = createIllegalStateException(exceptionMessage); + + logger.atWarning() + .addKeyValue("connection\tId", "foo") + .addKeyValue("linkName", "\rbar") + .log("hello {}, \"and\" {more}", "world", runtimeException); + + + String escapedExceptionMessage = "An exception \\tmessage with \\\"special characters\\\"\\r\\n"; + + String expectedMessage = "{\"az.sdk.message\":\"hello world, \\\"and\\\" {more}\",\"exception\":\"" + escapedExceptionMessage + "\",\"connection\\tId\":\"foo\",\"linkName\":\"\\rbar\"}"; + if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { + expectedMessage += System.lineSeparator() + runtimeException.toString() + System.lineSeparator() + "\tat " + runtimeException.getStackTrace()[0].toString(); + } + + assertMessage( + expectedMessage, + byteArraySteamToString(logCaptureStream), + logLevelToConfigure, + LogLevel.WARNING); + } + + /** + * Tests logging with context when cause is set + */ + @ParameterizedTest + @MethodSource("provideLogLevels") + public void logWithContextWithThrowableInCause(LogLevel logLevelToConfigure) { + setupLogLevel(logLevelToConfigure.getLogLevel()); + ClientLogger logger = new ClientLogger(ClientLoggerTests.class); + + String exceptionMessage = "An exception message"; + RuntimeException runtimeException = createIllegalStateException(exceptionMessage); + + assertSame(runtimeException, logger.atWarning() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", "bar") + .log(runtimeException)); + + String message = "{\"az.sdk.message\":\"\",\"exception\":\"" + exceptionMessage + "\",\"connectionId\":\"foo\",\"linkName\":\"bar\"}"; + if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { + message += System.lineSeparator() + runtimeException.toString() + System.lineSeparator() + "\tat " + runtimeException.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"); @@ -454,6 +719,15 @@ private static String byteArraySteamToString(ByteArrayOutputStream stream) { } } + private void assertMessage(String expectedMessage, String fullLog, LogLevel configuredLevel, LogLevel loggedLevel) { + if (loggedLevel.compareTo(configuredLevel) >= 0) { + // remove date/time/level/etc from fullMessage + assertEquals(expectedMessage + System.lineSeparator(), fullLog.substring(fullLog.indexOf(" - ") + 3)); + } else { + assertEquals("", fullLog); + } + } + private static Stream singleLevelCheckSupplier() { return Stream.of( // Supported logging level set to VERBOSE. diff --git a/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/LoggingBenchmark.java b/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/LoggingBenchmark.java new file mode 100644 index 0000000000000..7b22e7e2867ca --- /dev/null +++ b/sdk/core/azure-core/src/test/java/com/azure/core/util/logging/LoggingBenchmark.java @@ -0,0 +1,77 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package com.azure.core.util.logging; + +import com.azure.core.util.Configuration; +import org.openjdk.jmh.Main; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.Fork; +import org.openjdk.jmh.annotations.Measurement; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.OutputTimeUnit; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.Warmup; +import org.openjdk.jmh.runner.RunnerException; + +import java.io.IOException; +import java.io.OutputStream; +import java.io.PrintStream; +import java.util.concurrent.TimeUnit; + +import static com.azure.core.util.Configuration.PROPERTY_AZURE_LOG_LEVEL; + +@Fork(3) +@Warmup(iterations = 2, time = 2) +@Measurement(iterations = 2, time = 5) +@BenchmarkMode(Mode.AverageTime) +@OutputTimeUnit(TimeUnit.NANOSECONDS) +@State(Scope.Thread) +public class LoggingBenchmark { + ClientLogger logger; + + @Setup + public void setup() { + Configuration.getGlobalConfiguration().put(PROPERTY_AZURE_LOG_LEVEL, String.valueOf(LogLevel.WARNING)); + this.logger = new ClientLogger(LoggingBenchmark.class); + + System.setOut(new PrintStream(new OutputStream() { + @Override + public void write(int b) throws IOException { + } + })); + } + + @Benchmark + public void loggingAtDisabledLevel() { + logger.info("hello, connectionId={}, linkName={}", "foo", 1); + } + + @Benchmark + public void loggingAtDisabledLevelWithContext() { + logger.atInfo() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", 1) + .log("hello"); + } + + @Benchmark + public void loggingAtEnabledLevel() { + logger.error("hello, connectionId={}, linkName={}", "foo", 1); + } + + @Benchmark + public void loggingAtEnabledLevelWithContext() { + logger.atError() + .addKeyValue("connectionId", "foo") + .addKeyValue("linkName", 1) + .log("hello"); + } + + public static void main(String... args) throws IOException, RunnerException { + Main.main(args); + } +}