concurrent-api: defer logging during CapturedContextProviders initial…

…ization (#3202)

Motivation:

The MDC utilities depend on the AsyncContext for storing properties.
This can create a cyclical dependency since we try to log the
loaded providers as part of the initialization.

Modifications:

- In CapturedContextProviders, submit logging to a different thread so that
  it will happen 'later' after the class initialization is complete.
- Use a try/catch when trying to determine the log level in
  `DefaultAsyncContextProvider`.

servicetalk-concurrent-api/gradle/checkstyle/suppressions.xml

@@ -32,4 +32,7 @@
   <!-- Extra whitespace makes it easier to read doNotFailOnInputStreamWithBrokenAvailableCall() stream inputs -->
   <suppress checks="SingleSpaceSeparator"
             files="io[\\/]servicetalk[\\/]concurrent[\\/]api[\\/]FromInputStreamPublisherTest.java"/>
+  <!--  We can't log at this point, so we must surface errors through the console-->
+  <suppress id="ConsolePrint"
+            files="io[\\/]servicetalk[\\/]concurrent[\\/]api[\\/]DefaultAsyncContextProvider.java"/>
 </suppressions>

servicetalk-concurrent-api/src/main/java/io/servicetalk/concurrent/api/CapturedContextProviders.java

@@ -26,13 +26,18 @@
 import static java.util.Collections.unmodifiableList;
 
 final class CapturedContextProviders {
-
-    private static final Logger LOGGER = LoggerFactory.getLogger(CapturedContextProviders.class);
     private static final List<CapturedContextProvider> PROVIDERS;
 
     static {
         final ClassLoader classLoader = CapturedContextProviders.class.getClassLoader();
-        PROVIDERS = loadProviders(CapturedContextProvider.class, classLoader, LOGGER);
+        List<CapturedContextProvider> providers = emptyList();
+        try {
+            providers = loadProviders(CapturedContextProvider.class, classLoader);
+        } catch (Throwable ex) {
+            runLater(() ->
+                    getLogger().error("Failed to load {} instances", CapturedContextProvider.class.getName(), ex));
+        }
+        PROVIDERS = providers;
     }
 
     private CapturedContextProviders() {
@@ -43,20 +48,32 @@ static List<CapturedContextProvider> providers() {
         return PROVIDERS;
     }
 
-    // TODO: this was copied from `ServiceLoaderUtils` because the `CapturedContextProvider` interface is package
-    //  private and the call to `ServiceLoader.load(..)` can only load implementations for types that are visible
-    //  to the package from which it is called (because it checks if it's accessible by checking stack trace).
-    //  One we make CapturedContextProvider public we can return to using ServiceLoaderUtils.
-    private static <T> List<T> loadProviders(final Class<T> clazz, final ClassLoader classLoader, final Logger logger) {
+    // This was copied from `ServiceLoaderUtils` because the implementation there logs the result, which normally
+    // wouldn't be a problem but as it turns out things like the MDC logging utils depend on the AsyncContext which
+    // may result in a cyclical dependency in class initialization.
+    private static <T> List<T> loadProviders(final Class<T> clazz, final ClassLoader classLoader) {
         final List<T> list = new ArrayList<>(0);
         for (T provider : ServiceLoader.load(clazz, classLoader)) {
             list.add(provider);
         }
         if (list.isEmpty()) {
-            logger.debug("ServiceLoader {}(s) registered: []", clazz.getSimpleName());
+            runLater(() -> getLogger().debug("ServiceLoader {}(s) registered: []", clazz.getSimpleName()));
             return emptyList();
         }
-        logger.info("ServiceLoader {}(s) registered: {}", clazz.getSimpleName(), list);
+        runLater(() -> getLogger().info("ServiceLoader {}(s) registered: {}", clazz.getSimpleName(), list));
         return unmodifiableList(list);
     }
+
+    // We have to run logging code 'later' because of cyclical dependency issues that can arise if logging depends
+    // on the AsyncContext.
+    static void runLater(Runnable runnable) {
+        Thread t = new Thread(runnable);
+        t.setDaemon(true);
+        t.setName(CapturedContextProviders.class.getSimpleName() + "-logging");
+        t.start();
+    }
+
+    private static Logger getLogger() {
+        return LoggerFactory.getLogger(CapturedContextProviders.class);
+    }
 }

servicetalk-concurrent-api/src/main/java/io/servicetalk/concurrent/api/DefaultAsyncContextProvider.java

@@ -41,9 +41,8 @@ class DefaultAsyncContextProvider implements AsyncContextProvider {
             withInitial(DefaultAsyncContextProvider::newContextMap);
 
     private static final Logger LOGGER = LoggerFactory.getLogger(DefaultAsyncContextProvider.class);
-    private static final boolean NO_DEBUG_LOGGING = !LOGGER.isDebugEnabled();
-
     static final AsyncContextProvider INSTANCE = new DefaultAsyncContextProvider();
+    private static final boolean NO_DEBUG_LOGGING = isNoDebugLogging();
 
     protected DefaultAsyncContextProvider() {
     }
@@ -379,4 +378,17 @@ private static ContextMap exchangeContext(ContextMap contextMap) {
     private static ContextMap newContextMap() {
         return new CopyOnWriteContextMap();
     }
+
+    @SuppressWarnings("PMD.SystemPrintln")
+    private static boolean isNoDebugLogging() {
+        try {
+            return !LOGGER.isDebugEnabled();
+        } catch (Exception ex) {
+            // Logger isn't initialized, so we have to send it to a console.
+            System.err.println("Could not evaluate logging level, considering debug level is disabled by default. " +
+                    "Cause:" + System.lineSeparator() + ex);
+            ex.printStackTrace(System.err);
+            return true;
+        }
+    }
 }

servicetalk-log4j2-mdc-utils/src/test/java/io/servicetalk/log4j2/mdc/utils/ServiceTalkThreadContextMapTest.java

@@ -44,6 +44,7 @@ class ServiceTalkThreadContextMapTest {
 
     @BeforeEach
     void verifyMDCSetup() {
+        logger.info("Attempting to log");
         assumeTrue(ThreadContext.getThreadContextMap() instanceof ServiceTalkThreadContextMap);
     }
 

servicetalk-log4j2-mdc-utils/src/test/resources/log4j2-test.xml

@@ -20,6 +20,13 @@
       <PatternLayout pattern="%d %30t a=%X{a} b=%X{b} c=%X{c} [%-5level] %-30logger{1} - %msg%n"/>
     </Console>
   </Appenders>
+
+<!--  We add the DynamicThresholdFilter to surface cyclical dependencies between MDC logging and the AsyncContext -->
+  <DynamicThresholdFilter key="USER_ROLE" defaultThreshold="ERROR" onMatch="ACCEPT" onMismatch="DENY">
+    <KeyValuePair key="ADMIN" value="INFO"/>
+    <KeyValuePair key="GUEST" value="DEBUG"/>
+  </DynamicThresholdFilter>
+
   <Loggers>
     <Logger name="io.netty" level="info"/>
     <Root level="debug">

servicetalk-opentracing-log4j2/src/test/java/io/servicetalk/opentracing/log4j2/ServiceTalkTracingThreadContextMapTest.java

@@ -26,6 +26,8 @@
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
 
+import java.util.Arrays;
+
 import static io.servicetalk.log4j2.mdc.utils.LoggerStringWriter.assertContainsMdcPair;
 import static io.servicetalk.opentracing.asynccontext.AsyncContextInMemoryScopeManager.SCOPE_MANAGER;
 import static io.servicetalk.opentracing.internal.TracingIdUtils.idOrNullAsValue;
@@ -43,7 +45,7 @@ public void setup() {
     }
 
     @AfterEach
-    public void tearDown() {
+    public void tearDown() throws Exception {
         loggerStringWriter.remove();
     }
 
@@ -61,7 +63,10 @@ void tracingInfoDisplayedPresentInLogsViaMDC() throws Exception {
         tracer.activateSpan(span);
 
         LOGGER.debug("testing logging and MDC");
-        String v = loggerStringWriter.stableAccumulated(1000);
+        // We need to filter out the lines that are not from this thread.
+        String v = Arrays.stream(loggerStringWriter.stableAccumulated(1000).split("\n"))
+                .filter(line -> line.contains(Thread.currentThread().getName()))
+                .reduce("", (a, b) -> a + "\n" + b);
         assertContainsMdcPair(v, "traceId=", span.context().toTraceId());
         assertContainsMdcPair(v, "spanId=", span.context().toSpanId());
         assertContainsMdcPair(v, "parentSpanId=", idOrNullAsValue(span.context().parentSpanId()));