Skip to content

AP-25788: Dump log buffer in shutdown hook if not yet initialized#80

Open
enplotz wants to merge 1 commit intomasterfrom
bug/AP-25788-node-logger-may-swallow-buffered-log
Open

AP-25788: Dump log buffer in shutdown hook if not yet initialized#80
enplotz wants to merge 1 commit intomasterfrom
bug/AP-25788-node-logger-may-swallow-buffered-log

Conversation

@enplotz
Copy link
Contributor

@enplotz enplotz commented Mar 21, 2026

AP-25788 (NodeLogger may swallow buffered log messages)

@enplotz enplotz requested a review from a team as a code owner March 21, 2026 21:07
@enplotz enplotz requested review from Copilot and knime-ghub-bot and removed request for a team and Copilot March 21, 2026 21:07
@enplotz enplotz force-pushed the bug/AP-25788-node-logger-may-swallow-buffered-log branch from e4f1c26 to 93454fb Compare March 21, 2026 21:19
Copilot AI review requested due to automatic review settings March 21, 2026 21:19
Copy link

Copilot AI left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR addresses AP-25788 by ensuring buffered startup log messages don’t get silently lost when the JVM shuts down before KNIME logging finishes initialization, by adding an emergency buffer dump mechanism and configuration knobs.

Changes:

  • Added a structured “drain result” (BufferContents) and a drain() API to extract buffered messages plus eviction metadata.
  • Installed a shutdown hook (on first pre-init log usage) that dumps buffered startup log messages to stdout/stderr with configurable minimum level.
  • Introduced environment variables to control the emergency dump target stream and minimum dump level.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 4 comments.

File Description
org.knime.core/src/eclipse/org/knime/core/node/logging/LogBuffer.java Adds BufferContents and a drain() method to retrieve buffered messages + eviction metadata in one shot.
org.knime.core/src/eclipse/org/knime/core/node/logging/KNIMELogger.java Installs an emergency shutdown hook and implements dumping of buffered startup logs to a PrintStream with level filtering.
org.knime.core/src/eclipse/org/knime/core/node/KNIMEConstants.java Adds env var constants to configure the emergency dump target and minimum level.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +315 to +355
private static void drainBufferedMessagesTo(final PrintStream out, final String reason) {
Objects.requireNonNull(out);
final LogBuffer.BufferContents contents;
synchronized (BUFFER) {
if (isEmergencyBufferDumped) {
return;
}
isEmergencyBufferDumped = true;
contents = BUFFER.drain();
}
if (contents.isEmpty()) {
return;
}

final var matchingMessages = Arrays.stream(contents.messages())
.filter(message -> message.level().isGreaterOrEqual(EMERGENCY_BUFFER_DUMP_MIN_LEVEL))
.toList();
final var shouldEmitEvictionNotice = contents.evictedEntries() > 0
&& contents.evictionMessageLevel().isGreaterOrEqual(EMERGENCY_BUFFER_DUMP_MIN_LEVEL);
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 logging emergency dump: %s. %s buffered. Minimum level: %s.%n",
reason, countMessages, EMERGENCY_BUFFER_DUMP_MIN_LEVEL);
if (shouldEmitEvictionNotice) {
out.printf("[%s] %d messages were evicted from the startup log buffer in total.%n",
contents.evictionMessageLevel(), contents.evictedEntries());
}
for (final var message : matchingMessages) {
out.printf("%s %s [%s] %s%n",
message.instant(), message.level(), message.name(), Objects.toString(message.message(), ""));
if (message.cause() != null) {
message.cause().printStackTrace(out);
}
}
out.println("End of KNIME startup logging emergency dump.");
out.flush();
}
Copy link

Copilot AI Mar 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

drainBufferedMessagesTo introduces non-trivial behavior (level filtering, eviction notice gating, and single-shot dumping via isEmergencyBufferDumped) but there are no tests covering it. Since this module already has JUnit coverage for KNIMELogger (see org.knime.core.tests/.../KNIMELoggerTest), it would be good to add tests that (a) buffer some messages before init, (b) invoke the dump with a PrintStream backed by a ByteArrayOutputStream, and (c) assert output respects EMERGENCY_BUFFER_DUMP_MIN_LEVEL and eviction notice behavior.

Copilot uses AI. Check for mistakes.
Comment on lines +227 to +233
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);
Copy link

Copilot AI Mar 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

drain() uses m_logBuffer.drainingIterator() which is explicitly documented as not thread-safe and requiring synchronization on the parent object. Since drain() is a new entry point for draining, it should either be synchronized or have equivalent Javadoc clearly stating the required external synchronization (e.g. synchronized(BUFFER) in KNIMELogger) to prevent accidental unsafe use later.

Suggested change
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);
synchronized (m_logBuffer) {
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);
}

Copilot uses AI. Check for mistakes.
Comment on lines +301 to +303
} catch (IllegalStateException | SecurityException ex) {
isShutdownHookInstalled.set(false);
EMERGENCY_BUFFER_DUMP_TARGET.println("Unable to register KNIME startup log shutdown hook:");
Copy link

Copilot AI Mar 21, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

installEmergencyBufferDumpHandlers() resets isShutdownHookInstalled to false when addShutdownHook throws. For IllegalStateException (shutdown already in progress), this will cause repeated failed attempts (and repeated stderr output) on subsequent log calls, and the buffered messages still won’t be dumped. Consider handling IllegalStateException separately by dumping the buffer immediately (or leaving the flag true to avoid retries), and only resetting the flag for SecurityException if you want to allow retry when permissions change.

Suggested change
} catch (IllegalStateException | SecurityException ex) {
isShutdownHookInstalled.set(false);
EMERGENCY_BUFFER_DUMP_TARGET.println("Unable to register KNIME startup log shutdown hook:");
} catch (IllegalStateException ex) {
// JVM shutdown is already in progress; we cannot register a shutdown hook anymore.
// Keep the flag set to avoid repeated failed attempts and dump buffered messages immediately.
EMERGENCY_BUFFER_DUMP_TARGET.println(
"Unable to register KNIME startup log shutdown hook because JVM shutdown is already in progress.");
ex.printStackTrace(EMERGENCY_BUFFER_DUMP_TARGET);
drainBufferedMessagesTo(EMERGENCY_BUFFER_DUMP_TARGET,
"JVM is shutting down before KNIME logging could finish initialization (emergency dump without shutdown hook)");
} catch (SecurityException ex) {
// Registration was blocked by a security manager; allow future retries by resetting the flag.
isShutdownHookInstalled.set(false);
EMERGENCY_BUFFER_DUMP_TARGET.println(
"Unable to register KNIME startup log shutdown hook due to security restrictions:");

Copilot uses AI. Check for mistakes.
@enplotz enplotz force-pushed the bug/AP-25788-node-logger-may-swallow-buffered-log branch 3 times, most recently from 5dfb7b7 to 054d4e9 Compare March 21, 2026 21:36
AP-25788 (NodeLogger may swallow buffered log messages)
@enplotz enplotz force-pushed the bug/AP-25788-node-logger-may-swallow-buffered-log branch from 054d4e9 to d5e61c2 Compare March 21, 2026 21:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants