From 2a6702386859e94c274c79dfad5830d36455d25b Mon Sep 17 00:00:00 2001 From: Chris Lee Date: Wed, 13 Mar 2019 11:52:34 -0700 Subject: [PATCH] Implementation & tests for SLF4J flogger backend Closes https://github.com/google/flogger/pull/61 RELNOTES=Adds a new `slf4j-backend-factory` artifact ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=238273653 --- BUILD | 1 + WORKSPACE | 4 +- slf4j/BUILD | 55 +++++ .../backend/slf4j/Slf4jBackendFactory.java | 54 +++++ .../backend/slf4j/Slf4jLoggerBackend.java | 219 ++++++++++++++++++ .../backend/slf4j/Slf4jBackendLoggerTest.java | 138 +++++++++++ 6 files changed, 469 insertions(+), 2 deletions(-) create mode 100644 slf4j/BUILD create mode 100644 slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jBackendFactory.java create mode 100644 slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jLoggerBackend.java create mode 100644 slf4j/src/test/java/com/google/common/flogger/backend/slf4j/Slf4jBackendLoggerTest.java diff --git a/BUILD b/BUILD index bf304b8c..df1072cd 100644 --- a/BUILD +++ b/BUILD @@ -14,6 +14,7 @@ package_group( "//api/...", "//google/...", "//log4j/...", + "//slf4j/...", "//tools/...", ], ) diff --git a/WORKSPACE b/WORKSPACE index 34d88df3..00c4c36f 100644 --- a/WORKSPACE +++ b/WORKSPACE @@ -16,8 +16,8 @@ load("@bazel_tools//tools/build_defs/repo:http.bzl", "http_archive") http_archive( name = "google_bazel_common", - strip_prefix = "bazel-common-0a14592ccc7d6018643d841ee61a29ae3e9d4684", - urls = ["https://github.com/google/bazel-common/archive/0a14592ccc7d6018643d841ee61a29ae3e9d4684.zip"], + strip_prefix = "bazel-common-f1115e0f777f08c3cdb115526c4e663005bec69b", + urls = ["https://github.com/google/bazel-common/archive/f1115e0f777f08c3cdb115526c4e663005bec69b.zip"], ) load("@google_bazel_common//:workspace_defs.bzl", "google_common_workspace_rules") diff --git a/slf4j/BUILD b/slf4j/BUILD new file mode 100644 index 00000000..c589360e --- /dev/null +++ b/slf4j/BUILD @@ -0,0 +1,55 @@ +# Copyright 2018 Google Inc. All Rights Reserved. +# +# Description: +# Flogger slf4j backend (google.github.io/flogger). + +package(default_visibility = ["//:internal"]) + +SLF4J_BACKEND_SRCS = glob(["src/main/java/**/*.java"]) + +java_library( + name = "slf4j_backend", + srcs = SLF4J_BACKEND_SRCS, + javacopts = ["-source 1.6 -target 1.6"], + tags = ["maven_coordinates=com.google.flogger:flogger-slf4j-backend:${project.version}"], + deps = [ + "//api", + "//api:system_backend", + "@google_bazel_common//third_party/java/slf4j_api", + ], +) + +load("//tools:maven.bzl", "pom_file") + +pom_file( + name = "pom", + artifact_id = "flogger-slf4j-backend", + artifact_name = "Flogger SLF4J Backend", + targets = [":slf4j_backend"], +) + +load("@google_bazel_common//tools/javadoc:javadoc.bzl", "javadoc_library") + +javadoc_library( + name = "javadoc", + srcs = SLF4J_BACKEND_SRCS, + root_packages = ["com.google.common.flogger.backend.slf4j"], + deps = [":slf4j_backend"], +) + +# ---- Unit Tests ---- + +load("@google_bazel_common//testing:test_defs.bzl", "gen_java_tests") + +gen_java_tests( + name = "slf4j_tests", + srcs = glob(["src/test/java/**/*.java"]), + deps = [ + ":slf4j_backend", + "//api", + "//api:testing", + "@google_bazel_common//third_party/java/junit", + "@google_bazel_common//third_party/java/mockito", + "@google_bazel_common//third_party/java/slf4j_api", + ], +) diff --git a/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jBackendFactory.java b/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jBackendFactory.java new file mode 100644 index 00000000..f15154ad --- /dev/null +++ b/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jBackendFactory.java @@ -0,0 +1,54 @@ +/* + * Copyright (C) 2018 The Flogger Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.common.flogger.backend.slf4j; + +import com.google.common.flogger.backend.LoggerBackend; +import com.google.common.flogger.backend.system.BackendFactory; +import org.slf4j.LoggerFactory; + +/** + * BackendFactory for SLF4J. + * + *

To configure this backend for Flogger set the following system property (also see {@link + * com.google.common.flogger.backend.system.DefaultPlatform}): + * + *

+ */ +public final class Slf4jBackendFactory extends BackendFactory { + + private static final Slf4jBackendFactory INSTANCE = new Slf4jBackendFactory(); + + /** This method is expected to be called via reflection (and might otherwise be unused). */ + public static BackendFactory getInstance() { + return INSTANCE; + } + + @Override + public LoggerBackend create(String loggingClassName) { + return new Slf4jLoggerBackend(LoggerFactory.getLogger(loggingClassName.replace('$', '.'))); + } + + @Override + public String toString() { + return "SLF4J backend"; + } + + private Slf4jBackendFactory() {} +} diff --git a/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jLoggerBackend.java b/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jLoggerBackend.java new file mode 100644 index 00000000..97fbcbd9 --- /dev/null +++ b/slf4j/src/main/java/com/google/common/flogger/backend/slf4j/Slf4jLoggerBackend.java @@ -0,0 +1,219 @@ +/* + * Copyright (C) 2018 The Flogger Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.common.flogger.backend.slf4j; + +import com.google.common.flogger.backend.LogData; +import com.google.common.flogger.backend.LoggerBackend; +import com.google.common.flogger.backend.Metadata; +import com.google.common.flogger.backend.SimpleMessageFormatter; +import java.util.logging.Level; +import org.slf4j.Logger; + +/** A logging backend that uses slf4j to output log statements. */ +final class Slf4jLoggerBackend extends LoggerBackend + implements SimpleMessageFormatter.SimpleLogHandler { + + private final Logger logger; + + Slf4jLoggerBackend(Logger logger) { + if (logger == null) { + throw new NullPointerException("logger is required"); + } + this.logger = logger; + } + + // represents the log levels supported by SLF4J, used internally to dispatch calls accordingly + private enum Slf4jLogLevel { + TRACE, + DEBUG, + INFO, + WARN, + ERROR + } + + /** + * Adapts the JUL level to SLF4J level per the below mapping: + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + * + *
JULSLF4J
FINESTTRACE
FINERTRACE
FINEDEBUG
CONFIGDEBUG
INFOINFO
WARNINGWARN
SEVEREERROR
+ * + *

Custom JUL levels are mapped to the next-lowest standard JUL level; for example, a custom + * level at 750 (between INFO:800 and CONFIG:700) would map to the same as CONFIG (DEBUG). + * + *

It isn't expected that the JUL levels 'ALL' or 'OFF' are passed into this method; doing so + * will throw an IllegalArgumentException, as those levels are for configuration, not logging + * + * @param level the JUL level to map; any standard or custom JUL level, except for ALL or OFF + * @return the MappedLevel object representing the SLF4J adapters appropriate for the requested + * log level; never null. + */ + private static Slf4jLogLevel mapToSlf4jLogLevel(Level level) { + // Performance consideration: mapToSlf4jLogLevel is a very hot method, called even when + // logging is disabled. Allocations (and other latency-introducing constructs) should be avoided + int requestedLevel = level.intValue(); + + // Flogger shouldn't allow ALL or OFF to be used for logging + // if Flogger does add this check to the core library it can be removed here (and should be, + // as this method is on the critical performance path for determining whether log statements + // are disabled, hence called for all log statements) + if (requestedLevel == Level.ALL.intValue() || requestedLevel == Level.OFF.intValue()) { + throw new IllegalArgumentException("Unsupported log level: " + level); + } + + if (requestedLevel < Level.FINE.intValue()) { + return Slf4jLogLevel.TRACE; + } + + if (requestedLevel < Level.INFO.intValue()) { + return Slf4jLogLevel.DEBUG; + } + + if (requestedLevel < Level.WARNING.intValue()) { + return Slf4jLogLevel.INFO; + } + + if (requestedLevel < Level.SEVERE.intValue()) { + return Slf4jLogLevel.WARN; + } + + return Slf4jLogLevel.ERROR; + } + + @Override + public String getLoggerName() { + return logger.getName(); + } + + @Override + public boolean isLoggable(Level level) { + // Performance consideration: isLoggable is a very hot method, called even when logging is + // disabled. Allocations (and any other latency-introducing constructs) should be avoided + Slf4jLogLevel slf4jLogLevel = mapToSlf4jLogLevel(level); + + // dispatch to each level-specific method as SLF4J doesn't expose a logger.log( level, ... ) + switch (slf4jLogLevel) { + case TRACE: + return logger.isTraceEnabled(); + case DEBUG: + return logger.isDebugEnabled(); + case INFO: + return logger.isInfoEnabled(); + case WARN: + return logger.isWarnEnabled(); + case ERROR: + return logger.isErrorEnabled(); + } + throw new AssertionError("Unknown SLF4J log level: " + slf4jLogLevel); + } + + @Override + public void log(LogData data) { + SimpleMessageFormatter.format(data, this); + } + + @Override + public void handleError(RuntimeException exception, LogData badData) { + StringBuilder errorMsg = new StringBuilder(200); + errorMsg.append("LOGGING ERROR: "); + errorMsg.append(exception.getMessage()); + errorMsg.append('\n'); + formatBadLogData(badData, errorMsg); + + // log at ERROR to ensure visibility + logger.error(errorMsg.toString(), exception); + } + + // based on com.google.common.flogger.backend.system.AbstractLogRecord.safeAppend + private static void formatBadLogData(LogData data, StringBuilder out) { + out.append(" original message: "); + if (data.getTemplateContext() == null) { + out.append(data.getLiteralArgument()); + } else { + // We know that there's at least one argument to display here. + out.append(data.getTemplateContext().getMessage()); + out.append("\n original arguments:"); + for (Object arg : data.getArguments()) { + out.append("\n ").append(SimpleMessageFormatter.safeToString(arg)); + } + } + Metadata metadata = data.getMetadata(); + if (metadata.size() > 0) { + out.append("\n metadata:"); + for (int n = 0; n < metadata.size(); n++) { + out.append("\n "); + out.append(metadata.getKey(n).getLabel()).append(": ").append(metadata.getValue(n)); + } + } + out.append("\n level: ").append(data.getLevel()); + out.append("\n timestamp (nanos): ").append(data.getTimestampNanos()); + out.append("\n class: ").append(data.getLogSite().getClassName()); + out.append("\n method: ").append(data.getLogSite().getMethodName()); + out.append("\n line number: ").append(data.getLogSite().getLineNumber()); + } + + @Override + public void handleFormattedLogMessage(Level level, String message, Throwable thrown) { + Slf4jLogLevel slf4jLogLevel = mapToSlf4jLogLevel(level); + + // dispatch to each level-specific method, as SLF4J doesn't expose a logger.log( level, ... ) + switch (slf4jLogLevel) { + case TRACE: + logger.trace(message, thrown); + return; + case DEBUG: + logger.debug(message, thrown); + return; + case INFO: + logger.info(message, thrown); + return; + case WARN: + logger.warn(message, thrown); + return; + case ERROR: + logger.error(message, thrown); + return; + } + throw new AssertionError("Unknown SLF4J log level: " + slf4jLogLevel); + } +} diff --git a/slf4j/src/test/java/com/google/common/flogger/backend/slf4j/Slf4jBackendLoggerTest.java b/slf4j/src/test/java/com/google/common/flogger/backend/slf4j/Slf4jBackendLoggerTest.java new file mode 100644 index 00000000..38172f0a --- /dev/null +++ b/slf4j/src/test/java/com/google/common/flogger/backend/slf4j/Slf4jBackendLoggerTest.java @@ -0,0 +1,138 @@ +/* + * Copyright (C) 2018 The Flogger Authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.google.common.flogger.backend.slf4j; + +import static org.junit.Assert.fail; +import static org.mockito.Mockito.inOrder; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoMoreInteractions; +import static org.mockito.Mockito.verifyZeroInteractions; + +import com.google.common.flogger.LogContext; +import com.google.common.flogger.MetadataKey; +import com.google.common.flogger.backend.LogData; +import com.google.common.flogger.backend.LoggerBackend; +import com.google.common.flogger.parser.ParseException; +import com.google.common.flogger.testing.FakeLogData; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.JUnit4; +import org.mockito.InOrder; +import org.slf4j.Logger; + +@RunWith(JUnit4.class) +public class Slf4jBackendLoggerTest { + + private static final MetadataKey COUNT_KEY = MetadataKey.single("count", Integer.class); + private static final MetadataKey ID_KEY = MetadataKey.single("id", String.class); + + private static LoggerBackend newBackend(Logger logger) { + return new Slf4jLoggerBackend(logger); + } + + @Test + public void testMessage() { + Logger logger = mock(Logger.class); + LoggerBackend backend = newBackend(logger); + + backend.log(FakeLogData.of("Hello World")); + backend.log(FakeLogData.withPrintfStyle("Hello %s %s", "Foo", "Bar")); + + InOrder inOrder = inOrder(logger); + inOrder.verify(logger).info("Hello World", (Throwable) null); + inOrder.verify(logger).info("Hello Foo Bar", (Throwable) null); + verifyNoMoreInteractions(logger); + } + + @Test + public void testMetadata() { + Logger logger = mock(Logger.class); + LoggerBackend backend = newBackend(logger); + + backend.log( + FakeLogData.withPrintfStyle("Foo='%s'", "bar") + .addMetadata(COUNT_KEY, 23) + .addMetadata(ID_KEY, "test ID")); + + verify(logger).info("Foo='bar' [CONTEXT count=23 id=\"test ID\" ]", (Throwable) null); + verifyNoMoreInteractions(logger); + } + + @Test + public void testLevels() { + Logger logger = mock(Logger.class); + LoggerBackend backend = newBackend(logger); + + backend.log(FakeLogData.of("finest").setLevel(java.util.logging.Level.FINEST)); + backend.log(FakeLogData.of("finer").setLevel(java.util.logging.Level.FINER)); + backend.log(FakeLogData.of("fine").setLevel(java.util.logging.Level.FINE)); + backend.log(FakeLogData.of("config").setLevel(java.util.logging.Level.CONFIG)); + backend.log(FakeLogData.of("info").setLevel(java.util.logging.Level.INFO)); + backend.log(FakeLogData.of("warning").setLevel(java.util.logging.Level.WARNING)); + backend.log(FakeLogData.of("severe").setLevel(java.util.logging.Level.SEVERE)); + + InOrder inOrder = inOrder(logger); + inOrder.verify(logger).trace("finest", (Throwable) null); + inOrder.verify(logger).trace("finer", (Throwable) null); + inOrder.verify(logger).debug("fine", (Throwable) null); + inOrder.verify(logger).debug("config", (Throwable) null); + inOrder.verify(logger).info("info", (Throwable) null); + inOrder.verify(logger).warn("warning", (Throwable) null); + inOrder.verify(logger).error("severe", (Throwable) null); + verifyNoMoreInteractions(logger); + } + + @Test + public void testErrorHandling() { + Logger logger = mock(Logger.class); + LoggerBackend backend = newBackend(logger); + + LogData data = FakeLogData.withPrintfStyle("Hello %?X World", "ignored"); + try { + backend.log(data); + fail("expected ParseException"); + } catch (ParseException expected) { + verifyZeroInteractions(logger); + backend.handleError(expected, data); + verify(logger) + .error( + "LOGGING ERROR: invalid flag: Hello %[?]X World\n" + + " original message: Hello %?X World\n" + + " original arguments:\n" + + " ignored\n" + + " level: INFO\n" + + " timestamp (nanos): 0\n" + + " class: com.google.FakeClass\n" + + " method: fakeMethod\n" + + " line number: 123", + expected); + verifyNoMoreInteractions(logger); + } + } + + @Test + public void testWithThrown() { + Logger logger = mock(Logger.class); + LoggerBackend backend = newBackend(logger); + + Throwable cause = new Throwable("Original Cause"); + backend.log(FakeLogData.of("Hello World").addMetadata(LogContext.Key.LOG_CAUSE, cause)); + + verify(logger).info("Hello World", cause); + } +}