From d5e61c28b1bb6d57c8415270f9b71df8670f0725 Mon Sep 17 00:00:00 2001 From: Manuel Hotz Date: Sat, 21 Mar 2026 21:42:31 +0100 Subject: [PATCH] AP-25788: Dump log buffer in shutdown hook if not yet initialized AP-25788 (NodeLogger may swallow buffered log messages) --- .../org/knime/core/node/KNIMEConstants.java | 16 ++ .../knime/core/node/logging/KNIMELogger.java | 138 ++++++++++++++++++ .../knime/core/node/logging/LogBuffer.java | 51 ++++++- 3 files changed, 197 insertions(+), 8 deletions(-) diff --git a/org.knime.core/src/eclipse/org/knime/core/node/KNIMEConstants.java b/org.knime.core/src/eclipse/org/knime/core/node/KNIMEConstants.java index d691ff5569..5762cbe6d4 100644 --- a/org.knime.core/src/eclipse/org/knime/core/node/KNIMEConstants.java +++ b/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 diff --git a/org.knime.core/src/eclipse/org/knime/core/node/logging/KNIMELogger.java b/org.knime.core/src/eclipse/org/knime/core/node/logging/KNIMELogger.java index f82397f791..13ea039724 100644 --- a/org.knime.core/src/eclipse/org/knime/core/node/logging/KNIMELogger.java +++ b/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); + } + } + } + + /** + * Dumps 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 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 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; } diff --git a/org.knime.core/src/eclipse/org/knime/core/node/logging/LogBuffer.java b/org.knime.core/src/eclipse/org/knime/core/node/logging/LogBuffer.java index 124087b050..452fae575d 100644 --- a/org.knime.core/src/eclipse/org/knime/core/node/logging/LogBuffer.java +++ b/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 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. + * + *

+ * Note: this method is not thread-safe. 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. *