Backport 5.5: AP-25788: Dump log buffer in shutdown hook if not yet initialized

org.knime.core/src/eclipse/org/knime/core/node/KNIMEConstants.java

@@ -130,6 +130,22 @@ public final class KNIMEConstants {
      */
     public static final String ENV_MAX_THREAD_COUNT = "KNIME_CORE_MAX_THREADS";
 
+    /**
+     * Environment variable controlling where the logging failsafe output is written.
+     *
+     * Supported values are {@code stderr} and {@code stdout}. The default is {@code stderr}, and any other value
+     * falls back to {@code stderr}.
+     */
+    public static final String ENV_LOGGING_FAILSAFE_TARGET = "KNIME_CORE_LOGGING_FAILSAFE_TARGET";
+
+    /**
+     * Environment variable controlling the minimum level written by the logging failsafe output.
+     *
+     * Supported values are log4j levels such as {@code DEBUG}, {@code INFO}, {@code WARN}, {@code ERROR}, and
+     * {@code FATAL}. The default is {@code DEBUG}, and any other value falls back to {@code DEBUG}.
+     */
+    public static final String ENV_LOGGING_FAILSAFE_MIN_LEVEL = "KNIME_CORE_LOGGING_FAILSAFE_MIN_LEVEL";
+
     /**
      * Java property name to specify the default temp directory for KNIME temp files (such as data files). This can be
      * changed in the preference pages and is by default the same as the java.io.tmpdir

org.knime.core/src/eclipse/org/knime/core/node/logging/KNIMELogger.java

@@ -56,9 +56,11 @@
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.InputStreamReader;
+import java.io.PrintStream;
 import java.io.Writer;
 import java.nio.file.Files;
 import java.nio.file.Path;
+import java.time.Instant;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.HashMap;
@@ -68,6 +70,7 @@
 import java.util.Objects;
 import java.util.Optional;
 import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.function.BiFunction;
 import java.util.function.Supplier;
 
@@ -89,6 +92,7 @@
 import org.knime.core.node.NodeLogger;
 import org.knime.core.node.NodeLogger.LEVEL;
 import org.knime.core.node.NodeLogger.NodeContextInformation;
+import org.knime.core.node.NodeLoggerPatternLayout;
 import org.knime.core.node.logging.LogBuffer.BufferedLogMessage;
 import org.knime.core.node.util.CheckUtils;
 import org.knime.core.node.workflow.WorkflowManager;
@@ -185,6 +189,18 @@ public void run() {
 
     private static volatile boolean isInitialized;
 
+    private static final PrintStream FAILSAFE_LOGGING_TARGET = initFailsafeLoggingTarget();
+
+    private static final Level FAILSAFE_LOGGING_MIN_LEVEL = initFailsafeLoggingMinLevel();
+
+    private static final Layout FAILSAFE_LOGGING_LAYOUT = initFailsafeLoggingLayout();
+
+    private static final AtomicBoolean isShutdownHookInstalled = new AtomicBoolean();
+
+    private static volatile boolean isFailsafeShutdownLoggingActive;
+
+    private static boolean isFailsafeBufferDumped;
+
     static boolean isInstanceLocationSet() {
         final var loc = Platform.getInstanceLocation();
         return loc != null && loc.isSet();
@@ -281,6 +297,108 @@ static synchronized void initializeLogging(final boolean logBufferedLogMessages)
         }
     }
 
+    private static void installFailsafeLoggingHandlers() {
+        if (isShutdownHookInstalled.compareAndSet(false, true)) {
+            try {
+                Runtime.getRuntime().addShutdownHook(new Thread(
+                    () -> drainBufferedMessagesTo(FAILSAFE_LOGGING_TARGET,
+                        "JVM is shutting down before KNIME logging could finish initialization"),
+                    "KNIME startup log dump"));
+            } catch (IllegalStateException | SecurityException ex) {
+                isShutdownHookInstalled.set(false);
+                FAILSAFE_LOGGING_TARGET.println("Unable to register KNIME startup log shutdown hook:");
+                ex.printStackTrace(FAILSAFE_LOGGING_TARGET);
+            }
+        }
+    }
+
+    /**
+     * Drains buffered startup log messages to the given stream.
+     *
+     * @param out the target stream
+     * @param reason a human-readable reason included in the dump header
+     */
+    private static void drainBufferedMessagesTo(final PrintStream out, final String reason) {
+        drainBufferedMessagesTo(out, reason, FAILSAFE_LOGGING_MIN_LEVEL);
+    }
+
+    private static void drainBufferedMessagesTo(final PrintStream out, final String reason, final Level minLevel) {
+        Objects.requireNonNull(out);
+        final LogBuffer.BufferContents contents;
+        synchronized (BUFFER) {
+            if (isFailsafeBufferDumped) {
+                return;
+            }
+            isFailsafeShutdownLoggingActive = true;
+            isFailsafeBufferDumped = true;
+            contents = BUFFER.drain();
+        }
+        if (contents.isEmpty()) {
+            return;
+        }
+
+        final var matchingMessages = Arrays.stream(contents.messages())
+            .filter(message -> message.level().isGreaterOrEqual(minLevel))
+            .toList();
+        final var shouldEmitEvictionNotice = contents.evictedEntries() > 0
+            && contents.evictionMessageLevel().isGreaterOrEqual(minLevel);
+        if (matchingMessages.isEmpty() && !shouldEmitEvictionNotice) {
+            return;
+        }
+
+        final var total = contents.messages().length + contents.evictedEntries();
+        final var countMessages = total > 1 ? "%d messages were".formatted(total) : "1 message was";
+        out.printf("KNIME startup failsafe logging dump: %s. %s buffered. Minimum level: %s.%n",
+            reason, countMessages, minLevel);
+        if (shouldEmitEvictionNotice) {
+            emitToFailsafeLoggingTarget(KNIMELogger.class.getName(), contents.evictionMessageLevel(),
+                "[*** Log incomplete: log buffer did wrap around -- %d messages were evicted from buffer in total ***]"
+                    .formatted(contents.evictedEntries()),
+                null, Instant.now());
+        }
+        for (final var message : matchingMessages) {
+            emitToFailsafeLoggingTarget(message.name(), message.level(), message.message(), message.cause(),
+                message.instant());
+        }
+        out.println("End of KNIME startup failsafe logging dump.");
+        out.flush();
+    }
+
+    private static void emitToFailsafeLoggingTarget(final String name, final Level level, final Object message,
+        final Throwable cause) {
+        if (!level.isGreaterOrEqual(FAILSAFE_LOGGING_MIN_LEVEL)) {
+            return;
+        }
+
+        emitToFailsafeLoggingTarget(name, level, message, cause, Instant.now());
+    }
+
+    private static void emitToFailsafeLoggingTarget(final String name, final Level level, final Object message,
+        final Throwable cause, final Instant instant) {
+        final var event = new LoggingEvent(name, Logger.getLogger(name), instant.toEpochMilli(), level, message, cause);
+        FAILSAFE_LOGGING_TARGET.print(FAILSAFE_LOGGING_LAYOUT.format(event));
+        if (cause != null && FAILSAFE_LOGGING_LAYOUT.ignoresThrowable()) {
+            cause.printStackTrace(FAILSAFE_LOGGING_TARGET);
+        }
+        FAILSAFE_LOGGING_TARGET.flush();
+    }
+
+    private static PrintStream initFailsafeLoggingTarget() {
+        final var configuredTarget = System.getenv(KNIMEConstants.ENV_LOGGING_FAILSAFE_TARGET);
+        return "stdout".equalsIgnoreCase(configuredTarget) ? System.out : System.err;
+    }
+
+    private static Level initFailsafeLoggingMinLevel() {
+        return Level.toLevel(System.getenv(KNIMEConstants.ENV_LOGGING_FAILSAFE_MIN_LEVEL), Level.DEBUG);
+    }
+
+    private static Layout initFailsafeLoggingLayout() {
+        final var layout = new NodeLoggerPatternLayout();
+        layout.setConversionPattern("%d{ISO8601} : %-5p : %t : %c{1} : %m%n");
+        layout.activateOptions();
+        return layout;
+    }
+
     private void initializeInternalLogger() {
         if (m_logger == null) {
             m_logger = new DelegatingLogger(m_name);
@@ -984,12 +1102,22 @@ private void log(final BufferedLogMessage bufferedMessage) {
      */
     public void log(final Level level, final Supplier<Object> messageSupplier, final boolean omitContext,
             final Throwable cause) {
+        Objects.requireNonNull(level, "Must not log a null level");
         // we double-check to avoid expensive locking
         if (!isInitialized()) {
+            if (isFailsafeShutdownLoggingActive) {
+                emitToFailsafeLoggingTarget(m_name, level, messageSupplier.get(), cause);
+                return;
+            }
+            installFailsafeLoggingHandlers();
             synchronized(BUFFER) {
                 // we need to check again now that we have the lock to see if someone else has initialized it in the
                 // meantime
                 if (!isInitialized()) {
+                    if (isFailsafeShutdownLoggingActive) {
+                        emitToFailsafeLoggingTarget(m_name, level, messageSupplier.get(), cause);
+                        return;
+                    }
                     BUFFER.log(level, m_name, messageSupplier.get(), cause);
                     return;
                 }
@@ -1008,10 +1136,20 @@ public void log(final Level level, final Supplier<Object> messageSupplier, final
      */
     public void log(final Level level, final Object message, final boolean omitContext,
             final Throwable cause) {
+        Objects.requireNonNull(level, "Must not log a null level");
         // we double-check to avoid expensive locking
         if (!isInitialized()) {
+            if (isFailsafeShutdownLoggingActive) {
+                emitToFailsafeLoggingTarget(m_name, level, message, cause);
+                return;
+            }
+            installFailsafeLoggingHandlers();
             synchronized(BUFFER) {
                 if (!isInitialized()) {
+                    if (isFailsafeShutdownLoggingActive) {
+                        emitToFailsafeLoggingTarget(m_name, level, message, cause);
+                        return;
+                    }
                     BUFFER.log(level, m_name, message, cause);
                     return;
                 }

org.knime.core/src/eclipse/org/knime/core/node/logging/LogBuffer.java

@@ -64,6 +64,19 @@
  */
 final class LogBuffer {
 
+    /**
+     * Drained buffer contents and any overflow metadata.
+     *
+     * @param messages buffered messages in insertion order
+     * @param evictedEntries total number of messages evicted from the buffer
+     * @param evictionMessageLevel log level to use for an overflow notice
+     */
+    record BufferContents(BufferedLogMessage[] messages, long evictedEntries, Level evictionMessageLevel) {
+        boolean isEmpty() {
+            return messages.length == 0;
+        }
+    }
+
     private final CircularFiFoBuffer m_logBuffer;
 
     LogBuffer(final int bufferSize) {
@@ -187,26 +200,48 @@ private int size() {
      * @param consumer consumer for buffered log messages
      */
     void drainTo(final Consumer<BufferedLogMessage> consumer) {
-        if (!m_logBuffer.isEmpty()) {
+        final var contents = drain();
+        if (!contents.isEmpty()) {
             // we expect no NodeContext to be available at this point anyway
             final var omitCtx = true;
             final var logger = KNIMELogger.getLogger(KNIMELogger.class);
-            final var current = m_logBuffer.size();
-            final var evicted = m_logBuffer.getNumberOfEvictedEntries();
-            final var total = current + evicted;
+            final var total = contents.messages().length + contents.evictedEntries();
             final var countMessages = total > 1 ? "%d messages were".formatted(total) : "1 message was";
             logger.log(Level.DEBUG, () -> "%s logged before logging was initialized; see below..."
                 .formatted(countMessages), omitCtx, null);
-            if (evicted > 0) {
-                logger.log(m_logBuffer.m_levelForEvictionMessage,
+            if (contents.evictedEntries() > 0) {
+                logger.log(contents.evictionMessageLevel(),
                     () -> "[*** Log incomplete: log buffer did wrap around -- "
-                            + "%d messages were evicted from buffer in total ***]".formatted(evicted), omitCtx, null);
+                            + "%d messages were evicted from buffer in total ***]"
+                                .formatted(contents.evictedEntries()),
+                    omitCtx, null);
+            }
+            for (final var message : contents.messages()) {
+                consumer.accept(message);
             }
-            m_logBuffer.drainingIterator().forEachRemaining(consumer);
             logger.log(Level.DEBUG, "End of buffered log messages", omitCtx, null);
         }
     }
 
+    /**
+     * Drains and returns the current buffer contents.
+     *
+     * <p>
+     * <b>Note:</b> this method is <i>not thread-safe</i>. Callers must synchronize on the parent
+     * {@link LogBuffer} instance before invoking it.
+     *
+     * @return drained buffer contents in insertion order
+     */
+    BufferContents drain() {
+        final var current = m_logBuffer.size();
+        final var messages = new BufferedLogMessage[current];
+        final var iter = m_logBuffer.drainingIterator();
+        for (var i = 0; i < current; i++) {
+            messages[i] = iter.next();
+        }
+        return new BufferContents(messages, m_logBuffer.getNumberOfEvictedEntries(), m_logBuffer.m_levelForEvictionMessage);
+    }
+
     /**
      * Buffer the given message at the given level under the given logger name.
      *