Extends the functionality of the Log4j2 backend by supporting ScopedLoggingContext (Grpc).

This is a functional import of #242 with changes to formatting and other minor changes to satisfy internal checks.

RELNOTES=The log4j2 backend now supports `ScopedLoggingContext`.
PiperOrigin-RevId: 392510036

Author: sekaiser

log4j2/BUILD

@@ -15,13 +15,15 @@ LOG4J2_BACKEND_RESOURCES = glob(["src/main/resources/**"])
 java_library(
     name = "log4j2_backend",
     srcs = LOG4J2_BACKEND_SRCS,
-    javacopts = ["-source 7 -target 7"],
+    javacopts = ["-source 8 -target 8"],
     resources = LOG4J2_BACKEND_RESOURCES,
     tags = ["maven_coordinates=com.google.flogger:flogger-log4j2-backend:${project.version}"],
     deps = [
         "//api",
         "//api:system_backend",
+        "@com_google_errorprone_error_prone_annotations",
         "@google_bazel_common//third_party/java/log4j2",
+        "@org_checkerframework_checker_compat_qual",
     ],
 )
 
@@ -49,7 +51,8 @@ gen_java_tests(
         "//api",
         "//api:system_backend",
         "//api:testing",
-        "@google_bazel_common//third_party/java/guava",
+        "//google:flogger",
+        "//grpc:grpc_context",
         "@google_bazel_common//third_party/java/junit",
         "@google_bazel_common//third_party/java/log4j2",
         "@google_bazel_common//third_party/java/truth",

log4j2/src/main/java/com/google/common/flogger/backend/log4j2/Log4j2LogEventUtil.java

@@ -22,23 +22,34 @@
 
 import com.google.common.flogger.LogContext;
 import com.google.common.flogger.LogSite;
+import com.google.common.flogger.MetadataKey;
+import com.google.common.flogger.backend.BaseMessageFormatter;
 import com.google.common.flogger.backend.LogData;
 import com.google.common.flogger.backend.MessageUtils;
 import com.google.common.flogger.backend.Metadata;
+import com.google.common.flogger.backend.MetadataHandler;
 import com.google.common.flogger.backend.MetadataProcessor;
 import com.google.common.flogger.backend.Platform;
 import com.google.common.flogger.backend.SimpleMessageFormatter;
-import java.util.Collections;
-import java.util.Map;
+import com.google.common.flogger.context.ScopedLoggingContext;
+import com.google.common.flogger.context.Tags;
 import java.util.logging.Level;
+import java.util.stream.Collectors;
+import java.util.stream.StreamSupport;
 import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.config.Configuration;
+import org.apache.logging.log4j.core.config.DefaultConfiguration;
+import org.apache.logging.log4j.core.impl.ContextDataFactory;
 import org.apache.logging.log4j.core.impl.Log4jLogEvent;
 import org.apache.logging.log4j.core.time.Instant;
 import org.apache.logging.log4j.core.time.MutableInstant;
 import org.apache.logging.log4j.core.util.Throwables;
 import org.apache.logging.log4j.message.SimpleMessage;
+import org.apache.logging.log4j.util.StringMap;
 
-/** Helper to format LogData.
+/**
+ * Helper to format LogData.
  *
  * <p>Note: Any changes in this code should, as far as possible, be reflected in the equivalently
  * named log4j implementation. If the behaviour of this class starts to deviate from that of the
@@ -52,10 +63,34 @@ private Log4j2LogEventUtil() {}
   static LogEvent toLog4jLogEvent(String loggerName, LogData logData) {
     MetadataProcessor metadata =
         MetadataProcessor.forScopeAndLogSite(Platform.getInjectedMetadata(), logData.getMetadata());
-    String message = SimpleMessageFormatter.getDefaultFormatter().format(logData, metadata);
+
+    /*
+     * If no configuration file could be located, Log4j2 will use the DefaultConfiguration. This
+     * will cause logging output to go to the console and the context data will be ignored. This
+     * mechanism can be used to detect if a configuration file has been loaded (or if the default
+     * configuration was overwritten through the means of a configuration factory) by checking the
+     * type of the current configuration class.
+     *
+     * Be aware that the LoggerContext class is not part of Log4j2's public API and behavior can
+     * change with any minor release.
+     *
+     * For the future we are thinking about implementing a Flogger aware Log4j2 configuration (e.g.
+     * using a configuration builder with a custom ConfigurationFactory) to configure a formatter,
+     * which can perhaps be installed as default if nothing else is present. Then, we would not rely
+     * on Log4j2 internals.
+     */
+    LoggerContext ctx = LoggerContext.getContext(false);
+    Configuration config = ctx.getConfiguration();
+    String message;
+    if (config instanceof DefaultConfiguration) {
+      message = SimpleMessageFormatter.getDefaultFormatter().format(logData, metadata);
+    } else {
+      message =
+          BaseMessageFormatter.appendFormattedMessage(logData, new StringBuilder()).toString();
+    }
+
     Throwable thrown = metadata.getSingleValue(LogContext.Key.LOG_CAUSE);
-    return toLog4jLogEvent(
-        loggerName, logData, message, toLog4jLevel(logData.getLevel()), thrown);
+    return toLog4jLogEvent(loggerName, logData, message, toLog4jLevel(logData.getLevel()), thrown);
   }
 
   static LogEvent toLog4jLogEvent(String loggerName, RuntimeException error, LogData badData) {
@@ -71,21 +106,6 @@ private static LogEvent toLog4jLogEvent(
       String message,
       org.apache.logging.log4j.Level level,
       Throwable thrown) {
-    // The Mapped Diagnostic Context (MDC) allows to include additional metadata into logs which
-    // are written from the current thread.
-    //
-    // Example:
-    //  MDC.put("user.id", userId);
-    //  // do business logic that triggers logs
-    //  MDC.clear();
-    //
-    // By using '%X{key}' in the ConversionPattern of an appender this data can be included in the
-    // logs.
-    //
-    // We could include this data here by doing 'MDC.getContext()', but we don't want to encourage
-    // people using the log4j specific MDC. Instead this should be supported by a LoggingContext and
-    // usage of Flogger tags.
-    Map<String, String> mdcProperties = Collections.emptyMap();
 
     LogSite logSite = logData.getLogSite();
     StackTraceElement locationInfo =
@@ -105,7 +125,7 @@ private static LogEvent toLog4jLogEvent(
         .setThrown(thrown != null ? Throwables.getRootCause(thrown) : null)
         .setIncludeLocation(true)
         .setSource(locationInfo)
-        .setContextMap(mdcProperties)
+        .setContextData(createContextMap(logData))
         .build();
   }
 
@@ -180,4 +200,63 @@ private static void appendLogData(LogData data, StringBuilder out) {
     out.append("\n  method: ").append(data.getLogSite().getMethodName());
     out.append("\n  line number: ").append(data.getLogSite().getLineNumber());
   }
+
+  private static final MetadataHandler<MetadataKey.KeyValueHandler> HANDLER =
+      MetadataHandler.builder(
+              (MetadataHandler.ValueHandler<Object, MetadataKey.KeyValueHandler>)
+                  (key, value, kvh) -> {
+                    if (key.getClass().equals(LogContext.Key.TAGS.getClass())) {
+                      processTags(key, value, kvh);
+                    } else {
+                      // In theory a user can define a custom tag and use it as a MetadataKey. Those
+                      // keys shall be treated in the same way as LogContext.Key.TAGS when used as a
+                      // MetadataKey. Might be removed if visibility of MetadataKey#clazz changes.
+                      if (value instanceof Tags) {
+                        processTags(key, value, kvh);
+                      } else {
+                        ValueQueue.appendValues(key.getLabel(), value, kvh);
+                      }
+                    }
+                  })
+          .setDefaultRepeatedHandler(
+              (key, values, kvh) -> values.forEachRemaining(v -> kvh.handle(key.getLabel(), v)))
+          .build();
+
+  private static void processTags(
+      MetadataKey<Object> key, Object value, MetadataKey.KeyValueHandler kvh) {
+    ValueQueue valueQueue = ValueQueue.appendValueToNewQueue(value);
+    // Unlike single metadata (which is usually formatted as a single value), tags are always
+    // formatted as a list.
+    // Given the tags: tags -> foo=[bar], it will be formatted as tags=[foo=bar].
+    ValueQueue.appendValues(
+        key.getLabel(),
+        valueQueue.size() == 1
+            ? StreamSupport.stream(valueQueue.spliterator(), false).collect(Collectors.toList())
+            : valueQueue,
+        kvh);
+  }
+
+  /**
+   * We do not support {@code MDC.getContext()} and {@code NDC.getStack()} and we do not make any
+   * attempt to merge Log4j2 context data with Flogger's context data. Instead, users should use the
+   * {@link ScopedLoggingContext}.
+   *
+   * <p>Flogger's {@link ScopedLoggingContext} allows to include additional metadata and tags into
+   * logs which are written from current thread. This context data will be added to the log4j2
+   * event.
+   */
+  private static StringMap createContextMap(LogData logData) {
+    MetadataProcessor metadataProcessor =
+        MetadataProcessor.forScopeAndLogSite(Platform.getInjectedMetadata(), logData.getMetadata());
+
+    StringMap contextData = ContextDataFactory.createContextData(metadataProcessor.keyCount());
+    metadataProcessor.process(
+        HANDLER,
+        (key, value) ->
+            contextData.putValue(key, ValueQueue.maybeWrap(value, contextData.getValue(key))));
+
+    contextData.freeze();
+
+    return contextData;
+  }
 }

log4j2/src/main/java/com/google/common/flogger/backend/log4j2/ValueQueue.java

@@ -0,0 +1,191 @@
+/*
+ * Copyright (C) 2021 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.log4j2;
+
+import static com.google.common.flogger.util.Checks.checkNotNull;
+
+import com.google.common.flogger.MetadataKey;
+import com.google.common.flogger.context.Tags;
+import java.util.Iterator;
+import java.util.LinkedList;
+import java.util.List;
+import java.util.Objects;
+import org.checkerframework.checker.nullness.compatqual.NullableDecl;
+
+/**
+ * A simple FIFO queue linked-list implementation designed to store multiple metadata values in a
+ * StringMap. There are two aspects worth pointing out:
+ *
+ * <p>First, it is expected that a value queue always contains at least a single item. You cannot
+ * add null references to the queue and you cannot create an empty queue.
+ *
+ * <p>Second, it is expected to access the contents of the value queue via an iterator only. Hence
+ * we do not provide a method for taking the first item in the value queue..
+ *
+ * <p>Metadata values in Flogger always have unique keys, but those keys can have the same label.
+ * Because Log4j2 uses a {@code String} keyed map, we would risk clashing of values if we just used
+ * the label to store each value directly. This class lets us store a list of values for a single
+ * label while being memory efficient in the common case where each label really does only have one
+ * value.
+ */
+final class ValueQueue implements Iterable<Object> {
+  // Since the number of elements is almost never above 1 or 2, a LinkedList saves space.
+  private final List<Object> values = new LinkedList<>();
+
+  private ValueQueue() {}
+
+  static ValueQueue newQueue(Object item) {
+    checkNotNull(item, "item");
+    ValueQueue valueQueue = new ValueQueue();
+    valueQueue.put(item);
+    return valueQueue;
+  }
+
+  static Object maybeWrap(Object value, @NullableDecl Object existingValue) {
+    checkNotNull(value, "value");
+    if (existingValue == null) {
+      return value;
+    } else {
+      // This should only rarely happen, so a few small allocations seems acceptable.
+      ValueQueue existingQueue =
+          existingValue instanceof ValueQueue
+              ? (ValueQueue) existingValue
+              : ValueQueue.newQueue(existingValue);
+      existingQueue.put(value);
+      return existingQueue;
+    }
+  }
+
+  static void appendValues(String label, Object valueOrQueue, MetadataKey.KeyValueHandler kvh) {
+    if (valueOrQueue instanceof ValueQueue) {
+      for (Object value : (ValueQueue) valueOrQueue) {
+        emit(label, value, kvh);
+      }
+    } else {
+      emit(label, valueOrQueue, kvh);
+    }
+  }
+
+  /**
+   * Helper method for creating and initializing a value queue with a non-nullable value. If value
+   * is an instance of Tags, each tag will be added to the value queue.
+   */
+  static ValueQueue appendValueToNewQueue(Object value) {
+    ValueQueue valueQueue = new ValueQueue();
+    ValueQueue.emit(null, value, (k, v) -> valueQueue.put(v));
+    return valueQueue;
+  }
+
+  /**
+   * Emits a metadata label/value pair to a given {@code KeyValueHandler}, handling {@code Tags}
+   * values specially.
+   *
+   * <p>Tags are key-value mappings which cannot be modified or replaced. If you add the tag mapping
+   * {@code "foo" -> true} and later add {@code "foo" -> false}, you get "foo" mapped to both true
+   * and false. This is very deliberate since the key space for tags is global and the risk of two
+   * bits of code accidentally using the same tag name is real (e.g. you add "id=xyz" to a scope,
+   * but you see "id=abcd" because someone else added "id=abcd" in a context you weren't aware of).
+   *
+   * <p>Given three tag mappings:
+   * <ul>
+   *   <li>{@code "baz"} (no value)
+   *   <li>{@code "foo" -> true}
+   *   <li>{@code "foo" -> false}
+   * </ul>
+   *
+   * the value queue is going to store the mappings as:
+   * <pre>{@code
+   * tags=[baz, foo=false, foo=true]
+   * }</pre>
+   *
+   * <p>Reusing the label 'tags' is intentional as this allows us to store the flatten tags in
+   * Log4j2's ContextMap.
+   */
+  static void emit(String label, Object value, MetadataKey.KeyValueHandler kvh) {
+    if (value instanceof Tags) {
+      // Flatten tags to treat them as keys or key/value pairs, e.g. tags=[baz=bar, baz=bar2, foo]
+      ((Tags) value)
+          .asMap()
+          .forEach(
+              (k, v) -> {
+                if (v.isEmpty()) {
+                  kvh.handle(label, k);
+                } else {
+                  for (Object obj : v) {
+                    kvh.handle(label, k + "=" + obj);
+                  }
+                }
+              });
+    } else {
+      kvh.handle(label, value);
+    }
+  }
+
+  @Override
+  public Iterator<Object> iterator() {
+    return values.iterator();
+  }
+
+  void put(Object item) {
+    checkNotNull(item, "item");
+    values.add(item);
+  }
+
+  int size() {
+    return values.size();
+  }
+
+  /**
+   * Returns a string representation of the contents of the specified value queue.
+   *
+   * <ul>
+   *   <li>If the value queue is empty, the method returns an empty string.
+   *   <li>If the value queue contains a single element {@code a}, this method returns {@code
+   *       a.toString()}.
+   *   <li>Otherwise, the contents of the queue are formatted like a {@code List}.
+   * </ul>
+   */
+  @Override
+  public String toString() {
+    // This case shouldn't actually happen unless you use the value queue for storing emitted values
+    if (values.isEmpty()) {
+      return "";
+    }
+    // Consider using MessageUtils.safeToString() here.
+    if (values.size() == 1) {
+      return values.get(0).toString();
+    }
+    return values.toString();
+  }
+
+  @Override
+  public boolean equals(Object o) {
+    if (this == o) {
+      return true;
+    }
+    if (o == null || getClass() != o.getClass()) {
+      return false;
+    }
+    ValueQueue that = (ValueQueue) o;
+    return values.equals(that.values);
+  }
+
+  @Override
+  public int hashCode() {
+    return Objects.hashCode(values);
+  }
+}