Logging is skipped if the environment log level doesn't support logging at the informational or verbose level. - * All logging in this policy occurs at the information level.
- * - * @param environmentLogLevel Log level configured in the environment at the time logging begins. - * @return A flag indicating if logging should be skipped. - */ - private boolean shouldLoggingBeSkipped(int environmentLogLevel) { - return environmentLogLevel > LogLevel.INFORMATIONAL.getLogLevel(); - } - /* * Generates the redacted URL for logging. * @@ -317,9 +301,9 @@ private String getAllowedQueryString(String queryString) { * @param sb StringBuilder that is generating the log message. * @param logLevel Log level the environment is configured to use. */ - private void addHeadersToLogMessage(HttpHeaders headers, StringBuilder sb, int logLevel) { + private void addHeadersToLogMessage(ClientLogger logger, HttpHeaders headers, StringBuilder sb) { // Either headers shouldn't be logged or the logging level isn't set to VERBOSE, don't add headers. - if (!httpLogDetailLevel.shouldLogHeaders() || logLevel > LogLevel.VERBOSE.getLogLevel()) { + if (!httpLogDetailLevel.shouldLogHeaders() || logger.canLogAtLevel(LogLevel.VERBOSE)) { return; } diff --git a/sdk/core/azure-core/src/main/java/com/azure/core/implementation/LoggingUtil.java b/sdk/core/azure-core/src/main/java/com/azure/core/implementation/LoggingUtil.java deleted file mode 100644 index 3f7eb257a99e..000000000000 --- a/sdk/core/azure-core/src/main/java/com/azure/core/implementation/LoggingUtil.java +++ /dev/null @@ -1,30 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. - -package com.azure.core.implementation; - -import com.azure.core.util.Configuration; -import com.azure.core.util.logging.LogLevel; - -/** - * This class contains utility methods useful for logging. - */ -public final class LoggingUtil { - /** - * Retrieve the environment logging level which is used to determine if and what we are allowed to log. - * - *The value returned from this method should be used throughout a single logging event as it may change during - * the logging operation, this will help prevent difficult to debug timing issues.
- * - * @return Environment logging level if set, otherwise {@link LogLevel#NOT_SET}. - */ - public static LogLevel getEnvironmentLoggingLevel() { - String environmentLogLevel = Configuration.getGlobalConfiguration().get(Configuration.PROPERTY_AZURE_LOG_LEVEL); - - return LogLevel.fromString(environmentLogLevel); - } - - // Private constructor - private LoggingUtil() { - } -} diff --git a/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/DefaultLogger.java b/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/DefaultLogger.java new file mode 100644 index 000000000000..f0e43b22a419 --- /dev/null +++ b/sdk/core/azure-core/src/main/java/com/azure/core/implementation/logging/DefaultLogger.java @@ -0,0 +1,362 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package com.azure.core.implementation.logging; + +import com.azure.core.util.Configuration; +import com.azure.core.util.logging.LogLevel; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.time.LocalDateTime; +import java.time.format.DateTimeFormatter; +import org.slf4j.helpers.FormattingTuple; +import org.slf4j.helpers.MarkerIgnoringBase; +import org.slf4j.helpers.MessageFormatter; + +/** + * This class is an internal implementation of slf4j logger. + */ +public final class DefaultLogger extends MarkerIgnoringBase { + private static final long serialVersionUID = -144261058636441630L; + + private static final String AZURE_LOG_LEVEL = "AZURE_LOG_LEVEL"; + private static final DateTimeFormatter DATE_FORMAT = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm"); + + // The template forms the log message in a format: + // YYYY-MM-DD HH:MM [thread] [level] classpath - message + // E.g: 2020-01-09 12:35 [main] [WARNING] com.azure.core.DefaultLogger - This is my log message. + private static final String MESSAGE_TEMPLATE = "%s [%s] [%s] %s - %s%n"; + + private String classPath; + + /** + * Construct DefaultLogger for the given class. + * + * @param clazz Class creating the logger. + */ + public DefaultLogger(Class clazz) { + this(clazz.getName()); + } + + /** + * Construct DefaultLogger for the given class name. + * + * @param className Class name creating the logger. Will use class canonical name if exists, otherwise use the + * class name passes in. + */ + public DefaultLogger(String className) { + try { + this.classPath = Class.forName(className).getCanonicalName(); + } catch (ClassNotFoundException e) { + this.classPath = className; + } + } + + /** + * {@inheritDoc} + */ + @Override + public String getName() { + return classPath; + } + + /** + * {@inheritDoc} + */ + @Override + public boolean isTraceEnabled() { + String logLevelStr = Configuration.getGlobalConfiguration().get(AZURE_LOG_LEVEL); + LogLevel currentLogLevel = LogLevel.fromString(logLevelStr); + return currentLogLevel.getLogLevel() < LogLevel.VERBOSE.getLogLevel(); + } + + /** + * {@inheritDoc} + */ + @Override + public void trace(final String msg) { + logMessageWithFormat("TRACE", msg); + } + + /** + * {@inheritDoc} + */ + @Override + public void trace(final String format, final Object arg1) { + logMessageWithFormat("TRACE", format, arg1); + } + + /** + * {@inheritDoc} + */ + @Override + public void trace(final String format, final Object arg1, final Object arg2) { + logMessageWithFormat("TRACE", format, arg1, arg2); + } + + /** + * {@inheritDoc} + */ + @Override + public void trace(final String format, final Object... arguments) { + logMessageWithFormat("TRACE", format, arguments); + } + + /** + * {@inheritDoc} + */ + @Override + public void trace(final String msg, final Throwable t) { + log("TRACE", msg, t); + } + + /** + * {@inheritDoc} + */ + @Override + public boolean isDebugEnabled() { + return isLogLevelEnabledFromEnv(LogLevel.VERBOSE); + } + + @Override + public void debug(final String msg) { + logMessageWithFormat("DEBUG", msg); + } + + /** + * {@inheritDoc} + */ + @Override + public void debug(String format, Object arg) { + logMessageWithFormat("DEBUG", format, arg); + } + + /** + * {@inheritDoc} + */ + @Override + public void debug(final String format, final Object arg1, final Object arg2) { + logMessageWithFormat("DEBUG", format, arg1, arg2); + } + + /** + * {@inheritDoc} + */ + @Override + public void debug(String format, Object... args) { + logMessageWithFormat("DEBUG", format, args); + } + + /** + * {@inheritDoc} + */ + @Override + public void debug(final String msg, final Throwable t) { + log("DEBUG", msg, t); + } + + /** + * {@inheritDoc} + */ + @Override + public boolean isInfoEnabled() { + return isLogLevelEnabledFromEnv(LogLevel.INFORMATIONAL); + } + + + /** + * {@inheritDoc} + */ + @Override + public void info(final String msg) { + logMessageWithFormat("INFO", msg); + } + + /** + * {@inheritDoc} + */ + @Override + public void info(String format, Object arg) { + logMessageWithFormat("INFO", format, arg); + } + + /** + * {@inheritDoc} + */ + @Override + public void info(final String format, final Object arg1, final Object arg2) { + logMessageWithFormat("INFO", format, arg1, arg2); + } + + /** + * {@inheritDoc} + */ + @Override + public void info(String format, Object... args) { + logMessageWithFormat("INFO", format, args); + } + + /** + * {@inheritDoc} + */ + @Override + public void info(final String msg, final Throwable t) { + log("INFO", msg, t); + } + + /** + * {@inheritDoc} + */ + @Override + public boolean isWarnEnabled() { + return isLogLevelEnabledFromEnv(LogLevel.WARNING); + } + + /** + * {@inheritDoc} + */ + @Override + public void warn(final String msg) { + logMessageWithFormat("WARN", msg); + } + + /** + * {@inheritDoc} + */ + @Override + public void warn(String format, Object arg) { + logMessageWithFormat("WARN", format, arg); + } + + /** + * {@inheritDoc} + */ + @Override + public void warn(final String format, final Object arg1, final Object arg2) { + logMessageWithFormat("WARN", format, arg1, arg2); + } + + /** + * {@inheritDoc} + */ + @Override + public void warn(String format, Object... args) { + logMessageWithFormat("WARN", format, args); + } + + /** + * {@inheritDoc} + */ + @Override + public void warn(final String msg, final Throwable t) { + log("WARN", msg, t); + } + + /** + * {@inheritDoc} + */ + @Override + public boolean isErrorEnabled() { + return isLogLevelEnabledFromEnv(LogLevel.ERROR); + } + + /** + * {@inheritDoc} + */ + @Override + public void error(String format, Object arg) { + logMessageWithFormat("ERROR", format, arg); + } + + /** + * {@inheritDoc} + */ + @Override + public void error(final String msg) { + logMessageWithFormat("ERROR", msg); + } + + /** + * {@inheritDoc} + */ + @Override + public void error(final String format, final Object arg1, final Object arg2) { + logMessageWithFormat("ERROR", format, arg1, arg2); + } + + /** + * {@inheritDoc} + */ + @Override + public void error(String format, Object... args) { + logMessageWithFormat("ERROR", format, args); + } + + /** + * {@inheritDoc} + */ + @Override + public void error(final String msg, final Throwable t) { + log("ERROR", msg, t); + } + + private boolean isLogLevelEnabledFromEnv(LogLevel logLevel) { + String logLevelStr = Configuration.getGlobalConfiguration().get(AZURE_LOG_LEVEL); + LogLevel currentLogLevel = LogLevel.fromString(logLevelStr); + return logLevel.getLogLevel() >= currentLogLevel.getLogLevel(); + } + + /** + * Format and write the message according to the {@code MESSAGE_TEMPLATE}. + * + * @param levelName The level to log. + * @param format The log message format. + * @param arguments a list of arbitrary arguments taken in by format. + */ + private void logMessageWithFormat(String levelName, String format, Object... arguments) { + FormattingTuple tp = MessageFormatter.arrayFormat(format, arguments); + log(levelName, tp.getMessage(), tp.getThrowable()); + } + + /** + * Format and write the message according to the {@code MESSAGE_TEMPLATE}. + * + * @param levelName log level + * @param message The message itself + * @param t The exception whose stack trace should be logged + */ + private void log(String levelName, String message, Throwable t) { + String dateTime = getFormattedDate(); + String threadName = Thread.currentThread().getName(); + StringBuilder buf = new StringBuilder(64); + buf.append(String.format(MESSAGE_TEMPLATE, dateTime, threadName, levelName, classPath, message)); + writeWithThrowable(buf, t); + } + + /** + * Get the current time in Local time zone. + * + * @return The current time in {@code DATE_FORMAT} + */ + private String getFormattedDate() { + LocalDateTime now = LocalDateTime.now(); + return DATE_FORMAT.format(now); + } + + /** + * Write the log message with throwable stack trace if any. + * + * @param buf Take the log messages. + * @param t The exception whose stack trace should be logged + */ + void writeWithThrowable(StringBuilder buf, Throwable t) { + if (t != null) { + StringWriter sw = new StringWriter(); + try (PrintWriter pw = new PrintWriter(sw)) { + t.printStackTrace(pw); + buf.append(sw.toString()); + } + } + System.out.println(buf.toString()); + } +} 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 0938669d75a2..f07249162cb7 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 @@ -3,15 +3,14 @@ package com.azure.core.util.logging; +import com.azure.core.implementation.logging.DefaultLogger; import com.azure.core.util.Configuration; import com.azure.core.util.CoreUtils; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; - import java.util.Arrays; import java.util.Objects; - -import static com.azure.core.implementation.LoggingUtil.getEnvironmentLoggingLevel; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.helpers.NOPLogger; /** * This is a fluent logger helper class that wraps a pluggable {@link Logger}. @@ -50,9 +49,11 @@ 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. */ public ClientLogger(String className) { - logger = LoggerFactory.getLogger(className); + Logger initLogger = LoggerFactory.getLogger(className); + logger = initLogger instanceof NOPLogger ? new DefaultLogger(className) : initLogger; } /** @@ -69,7 +70,9 @@ public ClientLogger(String className) { * {@link Throwable}. */ public void verbose(String format, Object... args) { - log(LogLevel.VERBOSE, format, args); + if (logger.isDebugEnabled()) { + performLogging(LogLevel.VERBOSE, false, format, args); + } } /** @@ -86,7 +89,9 @@ public void verbose(String format, Object... args) { * {@link Throwable}. */ public void info(String format, Object... args) { - log(LogLevel.INFORMATIONAL, format, args); + if (logger.isInfoEnabled()) { + performLogging(LogLevel.INFORMATIONAL, false, format, args); + } } /** @@ -103,7 +108,9 @@ public void info(String format, Object... args) { * {@link Throwable}. */ public void warning(String format, Object... args) { - log(LogLevel.WARNING, format, args); + if (logger.isWarnEnabled()) { + performLogging(LogLevel.WARNING, false, format, args); + } } /** @@ -120,21 +127,8 @@ public void warning(String format, Object... args) { * {@link Throwable}. */ public void error(String format, Object... args) { - log(LogLevel.ERROR, format, args); - } - - /* - * This method logs the formattable message if the {@code logLevel} is enabled - * - * @param logLevel The log level at which this message should be logged - * @param format The formattable message to log - * @param args Arguments for the message, if an exception is being logged last argument is the throwable. - */ - private void log(LogLevel logLevel, String format, Object... args) { - LogLevel environmentLoggingLevel = getEnvironmentLoggingLevel(); - - if (canLogAtLevel(logLevel, environmentLoggingLevel)) { - performLogging(logLevel, environmentLoggingLevel, false, format, args); + if (logger.isErrorEnabled()) { + performLogging(LogLevel.ERROR, false, format, args); } } @@ -146,7 +140,13 @@ private void log(LogLevel logLevel, String format, Object... args) { * @throws NullPointerException If {@code runtimeException} is {@code null}. */ public RuntimeException logExceptionAsWarning(RuntimeException runtimeException) { - return logException(runtimeException, LogLevel.WARNING); + Objects.requireNonNull(runtimeException, "'runtimeException' cannot be null."); + if (!logger.isWarnEnabled()) { + return runtimeException; + } + + performLogging(LogLevel.WARNING, true, runtimeException.getMessage(), runtimeException); + return runtimeException; } /** @@ -157,29 +157,14 @@ public RuntimeException logExceptionAsWarning(RuntimeException runtimeException) * @throws NullPointerException If {@code runtimeException} is {@code null}. */ public RuntimeException logExceptionAsError(RuntimeException runtimeException) { - return logException(runtimeException, LogLevel.ERROR); - } - - private RuntimeException logException(RuntimeException runtimeException, LogLevel logLevel) { Objects.requireNonNull(runtimeException, "'runtimeException' cannot be null."); - - LogLevel environmentLoggingLevel = getEnvironmentLoggingLevel(); - - if (canLogAtLevel(logLevel, environmentLoggingLevel)) { - performLogging(logLevel, environmentLoggingLevel, true, runtimeException.getMessage(), runtimeException); + if (!logger.isErrorEnabled()) { + return runtimeException; } - return runtimeException; - } + performLogging(LogLevel.VERBOSE, true, runtimeException.getMessage(), runtimeException); - /** - * Determines if the environment and logger support logging at the given log level. - * - * @param logLevel The {@link LogLevel} being validated as supported. - * @return Flag indicating if the environment and logger support logging at the given log level. - */ - public boolean canLogAtLevel(LogLevel logLevel) { - return canLogAtLevel(logLevel, getEnvironmentLoggingLevel()); + return runtimeException; } /* @@ -188,8 +173,7 @@ public boolean canLogAtLevel(LogLevel logLevel) { * @param format formattable message. * @param args Arguments for the message, if an exception is being logged last argument is the throwable. */ - private void performLogging(LogLevel logLevel, LogLevel environmentLogLevel, boolean isExceptionLogging, - String format, Object... args) { + private void performLogging(LogLevel logLevel, boolean isExceptionLogging, String format, Object... args) { // If the logging level is less granular than verbose remove the potential throwable from the args. String throwableMessage = ""; if (doesArgsHaveThrowable(args)) { @@ -207,7 +191,7 @@ private void performLogging(LogLevel logLevel, LogLevel environmentLogLevel, boo * 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 (environmentLogLevel.getLogLevel() > LogLevel.VERBOSE.getLogLevel()) { + if (!logger.isDebugEnabled()) { args = removeThrowable(args); } } @@ -235,27 +219,19 @@ private void performLogging(LogLevel logLevel, LogLevel environmentLogLevel, boo // Don't do anything, this state shouldn't be possible. break; } + } - /* - * Determines if the environment and logger support logging at the given log level. + /** + * Determines if the app or environment logger support logging at the given log level. * * @param logLevel Logging level for the log message. - * @param environmentLoggingLevel Logging level the environment is set to support. * @return Flag indicating if the environment and logger are configured to support logging at the given log level. */ - private boolean canLogAtLevel(LogLevel logLevel, LogLevel environmentLoggingLevel) { - // Do not log if logLevel is null is not set. + public boolean canLogAtLevel(LogLevel logLevel) { if (logLevel == null) { return false; } - - // Attempting to log at a level not supported by the environment. - if (logLevel.getLogLevel() < environmentLoggingLevel.getLogLevel()) { - return false; - } - - // Determine if the logger configuration supports logging at the level. switch (logLevel) { case VERBOSE: return logger.isDebugEnabled(); diff --git a/sdk/core/azure-core/src/test/java/com/azure/core/http/policy/HttpLoggingPolicyTests.java b/sdk/core/azure-core/src/test/java/com/azure/core/http/policy/HttpLoggingPolicyTests.java index df464a9dbf01..80143d0cc40f 100644 --- a/sdk/core/azure-core/src/test/java/com/azure/core/http/policy/HttpLoggingPolicyTests.java +++ b/sdk/core/azure-core/src/test/java/com/azure/core/http/policy/HttpLoggingPolicyTests.java @@ -44,7 +44,7 @@ */ public class HttpLoggingPolicyTests { private static final String REDACTED = "REDACTED"; - private static final Context CONTEXT = new Context("caller-method", "HttpLoggingPolicyTests"); + private static final Context CONTEXT = new Context("caller-method", HttpLoggingPolicyTests.class.getName()); private String originalLogLevel; private PrintStream originalErr; @@ -64,9 +64,9 @@ public void prepareForTest() { System.setProperty("org.slf4j.simpleLogger.log.com.azure.core.util.logging.HttpLoggingPolicyTests", "trace"); // Override System.err as that is where SLF4J will log by default. - originalErr = System.err; + originalErr = System.out; logCaptureStream = new ByteArrayOutputStream(); - System.setErr(new PrintStream(logCaptureStream)); + System.setOut(new PrintStream(logCaptureStream)); } @AfterEach @@ -81,7 +81,7 @@ public void cleanupAfterTest() { System.clearProperty("org.slf4j.simpleLogger.log.com.azure.core.util.logging.HttpLoggingPolicyTests"); // Reset System.err to the original PrintStream. - System.setErr(originalErr); + System.setOut(originalErr); } /** 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 f7794a541168..f458caac5b94 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 @@ -28,9 +28,10 @@ public class ClientLoggerTests { private static final String PARAMETERIZED_TEST_NAME_TEMPLATE = "[" + ParameterizedTest.INDEX_PLACEHOLDER + "] " + ParameterizedTest.DISPLAY_NAME_PLACEHOLDER; - private PrintStream originalSystemErr; + private PrintStream originalSystemOut; private ByteArrayOutputStream logCaptureStream; + @BeforeEach public void setupLoggingConfiguration() { /* @@ -44,15 +45,16 @@ public void setupLoggingConfiguration() { * The default configuration for SLF4J's SimpleLogger uses System.err to log. Inject a custom PrintStream to * log into for the duration of the test to capture the log messages. */ - originalSystemErr = System.err; + originalSystemOut = System.out; logCaptureStream = new ByteArrayOutputStream(); - System.setErr(new PrintStream(logCaptureStream)); + System.setOut(new PrintStream(logCaptureStream)); } @AfterEach - public void revertLoggingConfiguration() { + public void revertLoggingConfiguration() throws Exception { System.clearProperty("org.slf4j.simpleLogger.log.com.azure.core.util.logging.ClientLoggerTests"); - System.setErr(originalSystemErr); + System.setOut(originalSystemOut); + logCaptureStream.close(); } private void setPropertyToOriginalOrClear(String propertyName, String originalValue) { @@ -75,6 +77,7 @@ public void logAtSupportedLevel(int logLevel) { String originalLogLevel = setupLogLevel(logLevel); logMessage(new ClientLogger(ClientLoggerTests.class), logLevel, logMessage); + setPropertyToOriginalOrClear(Configuration.PROPERTY_AZURE_LOG_LEVEL, originalLogLevel); String logValues = new String(logCaptureStream.toByteArray(), StandardCharsets.UTF_8); @@ -99,20 +102,6 @@ public void logAtUnsupportedLevel(int logLevel) { assertFalse(logValues.contains(logMessage)); } - /** - * Tests that logging when the environment log level is disabled nothing is logged. - * - * @param logLevel Logging level to log a message - */ - @ParameterizedTest(name = PARAMETERIZED_TEST_NAME_TEMPLATE) - @ValueSource(ints = { 1, 2, 3, 4 }) - public void logWhenLoggingInvalidNumeric(int logLevel) { - String logMessage = "This is a test"; - setupLogLevel(5); - assertThrows(IllegalArgumentException.class, () -> - logMessage(new ClientLogger(ClientLoggerTests.class), logLevel, logMessage)); - } - /** * Tests that logging when the environment log level is disabled nothing is logged. */ @@ -144,7 +133,7 @@ public void onlyLogExceptionMessage() { */ @Test public void logExceptionStackTrace() { - String logMessage = "This is an exception"; + String logMessage = "This is an exception fdsafdafdomcklamfd fdsafdafmlkdfmalsf fdsafdcacdalmd"; String exceptionMessage = "An exception message"; RuntimeException runtimeException = createRuntimeException(exceptionMessage); @@ -294,12 +283,11 @@ public void canLogAtLevel(int logLevelToConfigure, String logLevelToValidate, bo @ParameterizedTest(name = PARAMETERIZED_TEST_NAME_TEMPLATE) @ValueSource(strings = {"5", "invalid"}) public void canLogAtLevelInvalid(String logLevelToValidate) { - setupLogLevel(2); assertThrows(IllegalArgumentException.class, () -> LogLevel.fromString(logLevelToValidate)); } private String setupLogLevel(int logLevelToSet) { - String originalLogLevel = Configuration.getGlobalConfiguration().get(Configuration.PROPERTY_AZURE_CLOUD); + String originalLogLevel = Configuration.getGlobalConfiguration().get(Configuration.PROPERTY_AZURE_LOG_LEVEL); System.setProperty(Configuration.PROPERTY_AZURE_LOG_LEVEL, Integer.toString(logLevelToSet)); return originalLogLevel; }