From 79328b418bc53ac451024db8cd4a9501bbc14191 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Mon, 7 Sep 2026 19:20:34 +0000 Subject: [PATCH 1/7] Logging foundation: structured LogEvent, JUL handler, Log API enhancements --- apache-maven/pom.xml | 7 - .../maven/api/build/report/LogEvent.java | 165 +++++++++++ .../maven/api/build/report/LogLevel.java | 32 +-- .../maven/api/build/report/package-info.java | 33 +++ .../java/org/apache/maven/api/plugin/Log.java | 39 +-- compat/maven-embedder/pom.xml | 5 - impl/maven-cli/pom.xml | 9 - .../maven/cling/invoker/LookupInvoker.java | 13 +- .../logging/impl/LogbackConfiguration.java | 46 --- .../maven/slf4j-configuration.properties | 2 - .../maven/internal/build/DefaultLogEvent.java | 77 +++++ .../maven/internal/impl/DefaultLog.java | 110 +++++-- .../maven/logging/BuildEventListener.java | 3 +- .../logging/ProjectBuildLogAppender.java | 121 +++++++- .../logging/SimpleBuildEventListener.java | 6 +- .../maven/internal/impl/DefaultLogTest.java | 24 +- .../apache/maven/slf4j/MavenBaseLogger.java | 19 +- .../apache/maven/slf4j/MavenJulHandler.java | 272 ++++++++++++++++++ .../apache/maven/slf4j/MavenSimpleLogger.java | 52 +++- .../maven/slf4j/MavenJulHandlerTest.java | 101 +++++++ pom.xml | 12 - 21 files changed, 977 insertions(+), 171 deletions(-) create mode 100644 api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogEvent.java rename impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/Log4j2Configuration.java => api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogLevel.java (56%) create mode 100644 api/maven-api-core/src/main/java/org/apache/maven/api/build/report/package-info.java delete mode 100644 impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/LogbackConfiguration.java create mode 100644 impl/maven-core/src/main/java/org/apache/maven/internal/build/DefaultLogEvent.java create mode 100644 impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java create mode 100644 impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java diff --git a/apache-maven/pom.xml b/apache-maven/pom.xml index e02421bfdcda..1a96dfa49a29 100644 --- a/apache-maven/pom.xml +++ b/apache-maven/pom.xml @@ -78,13 +78,6 @@ under the License. ${slf4jVersion} runtime - - - org.slf4j - jul-to-slf4j - ${slf4jVersion} - runtime - org.apache.maven.resolver maven-resolver-connector-basic diff --git a/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogEvent.java b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogEvent.java new file mode 100644 index 000000000000..e48bc4bbb296 --- /dev/null +++ b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogEvent.java @@ -0,0 +1,165 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you 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 org.apache.maven.api.build.report; + +import java.time.Instant; + +import org.apache.maven.api.annotations.Experimental; +import org.apache.maven.api.annotations.Immutable; +import org.apache.maven.api.annotations.Nonnull; +import org.apache.maven.api.annotations.Nullable; + +/** + * A structured log event captured during the build. + *

+ * Each event carries the log level, timestamp, message, and optionally + * the logger name and a stack trace. This replaces raw log line strings + * in the build report, enabling programmatic filtering by level and + * correlation by timestamp. + *

+ * Events originating from the Maven Log API or from JUL + * ({@code java.util.logging}) carry additional source metadata: the + * source class name, source method name, and thread identifier. + * For Log API events the source class name is the mojo implementation + * FQCN; for JUL events it comes from {@code LogRecord}. Events from + * direct SLF4J logging have these fields set to {@code null}. + * + * @since 4.1.0 + */ +@Experimental +@Immutable +public interface LogEvent { + + /** + * When this log event was produced (wall-clock time). + * + * @return the event instant, never {@code null} + */ + @Nonnull + Instant timestamp(); + + /** + * The severity level of this log event. + * + * @return the log level, never {@code null} + */ + @Nonnull + LogLevel level(); + + /** + * The log message, without level prefix or timestamp formatting. + * + * @return the formatted message, never {@code null} + */ + @Nonnull + String message(); + + /** + * The name of the logger that produced this event + * (e.g. {@code "org.apache.maven.plugins.compiler.CompilerMojo"}). + * + * @return the logger name, or {@code null} if unavailable + */ + @Nullable + String loggerName(); + + /** + * The stack trace associated with this event, if an exception was logged. + *

+ * The trace is formatted as a multi-line string and may be truncated + * for very deep stack traces. + * + * @return the stack trace string, or {@code null} if no exception was logged + */ + @Nullable + String stackTrace(); + + /** + * The fully formatted log line as rendered for console output, including + * the level prefix, timestamp, and any ANSI styling applied by the logger. + *

+ * This is the string that would be printed to the terminal in verbose mode. + * Console renderers that just need pass-through output can use this directly, + * while renderers that apply custom formatting (e.g. rich mode) can use the + * structured fields ({@link #level()}, {@link #message()}) instead. + *

+ * May be {@code null} if the event was created outside the SLF4J pipeline + * (e.g. in tests or by programmatic construction). + * + * @return the formatted log line, or {@code null} + */ + @Nullable + String formattedMessage(); + + // ---- Source metadata (populated for Log API and JUL events) ---- + + /** + * The fully qualified class name of the source that issued the log call. + *

+ * For Maven Log API events this is the mojo implementation class name. + * For JUL events it is the value from {@code LogRecord.getSourceClassName()}. + * For direct SLF4J logging it is {@code null}. + * + * @return the source class name, or {@code null} + */ + @Nullable + default String sourceClassName() { + return null; + } + + /** + * The method name of the source that issued the log call. + *

+ * For Maven Log API events this is resolved via {@link StackWalker}. + * For JUL events it is the value from {@code LogRecord.getSourceMethodName()}. + * For direct SLF4J logging it is {@code null}. + * + * @return the source method name, or {@code null} + */ + @Nullable + default String sourceMethodName() { + return null; + } + + /** + * The thread identifier from which this log event originated. + *

+ * Populated for both Log API and JUL events. Returns {@code -1} + * if the thread ID is not available (i.e. for direct SLF4J events). + * + * @return the thread ID, or {@code -1} if unavailable + */ + default long threadId() { + return -1; + } + + /** + * A monotonically increasing sequence number for total ordering of + * log events, useful when multiple events share the same timestamp. + *

+ * Assigned by the logging pipeline when the event is captured, + * providing a global ordering across all event sources (Log API, + * JUL, and direct SLF4J). + * + * @return the sequence number, or {@code -1} if unavailable + */ + default long sequenceNumber() { + return -1; + } +} diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/Log4j2Configuration.java b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogLevel.java similarity index 56% rename from impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/Log4j2Configuration.java rename to api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogLevel.java index bbd487fa5f87..684ea610a5bc 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/Log4j2Configuration.java +++ b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/LogLevel.java @@ -16,29 +16,21 @@ * specific language governing permissions and limitations * under the License. */ -package org.apache.maven.cling.logging.impl; +package org.apache.maven.api.build.report; -import org.apache.maven.cling.logging.BaseSlf4jConfiguration; +import org.apache.maven.api.annotations.Experimental; /** - * Configuration for slf4j-log4j2. + * Log severity levels, mirroring the standard SLF4J levels. * - * @since 3.1.0 + * @since 4.1.0 + * @see LogEvent#level() */ -public class Log4j2Configuration extends BaseSlf4jConfiguration { - @Override - public void setRootLoggerLevel(Level level) { - String value = - switch (level) { - case DEBUG -> "debug"; - case INFO -> "info"; - default -> "error"; - }; - System.setProperty("maven.logging.root.level", value); - } - - @Override - public void activate() { - // no op - } +@Experimental +public enum LogLevel { + TRACE, + DEBUG, + INFO, + WARN, + ERROR } diff --git a/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/package-info.java b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/package-info.java new file mode 100644 index 000000000000..8aee68ff901e --- /dev/null +++ b/api/maven-api-core/src/main/java/org/apache/maven/api/build/report/package-info.java @@ -0,0 +1,33 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you 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. + */ + +/** + * Structured build report data model. + *

+ * This package provides structured representations of build execution + * data, including log events and (in future) full build reports. + * {@link org.apache.maven.api.build.report.LogEvent} is the foundational + * type representing a single structured log entry captured during the build. + * + * @since 4.1.0 + */ +@Experimental +package org.apache.maven.api.build.report; + +import org.apache.maven.api.annotations.Experimental; diff --git a/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java b/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java index 23175d07b1f7..e54c45a686d8 100644 --- a/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java +++ b/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java @@ -55,7 +55,8 @@ default boolean isTraceEnabled() { * messages that help users investigate their build * (for instance, why a module was recompiled). *

- * The default implementation is a no-op for backward compatibility. + * The default implementation is a no-op for backward compatibility + * with existing {@code Log} implementations. * * @param content the message to log */ @@ -63,7 +64,6 @@ default void trace(CharSequence content) {} /** * Sends a message (and accompanying exception) to the user at the trace error level. - * The error's stacktrace will be output when this error level is enabled. *

* The default implementation is a no-op for backward compatibility. * @@ -87,8 +87,6 @@ default void trace(Throwable error) {} * The supplier is only evaluated if trace is enabled. *

* The default implementation is a no-op for backward compatibility. - * - * @param content the message supplier */ default void trace(Supplier content) {} @@ -97,9 +95,6 @@ default void trace(Supplier content) {} * The supplier is only evaluated if trace is enabled. *

* The default implementation is a no-op for backward compatibility. - * - * @param content the message supplier - * @param error the error that caused this log */ default void trace(Supplier content, Throwable error) {} @@ -111,10 +106,9 @@ default void trace(Supplier content, Throwable error) {} /** * Sends a message to the user in the debug error level. *

- * Debug is intended for messages that help users investigate - * their build — for example, why a module was recompiled or what - * classpath was resolved. For Maven core internals, use - * {@link #trace(CharSequence)} instead. + * Debug is the recommended level for diagnostic output that helps + * plugin users troubleshoot build problems (e.g. resolved paths, + * computed values). For Maven core internals, prefer {@link #trace}. * * @param content the message to log */ @@ -242,22 +236,15 @@ default void trace(Supplier content, Throwable error) {} /** * Returns a child logger whose name is derived from this logger's name - * by appending a dot and the given suffix. - * - *

For example, if a plugin's logger is named - * {@code "org.apache.maven.plugins.compiler.CompilerMojo"}, - * then {@code child("diagnostics")} returns a logger named - * {@code "org.apache.maven.plugins.compiler.CompilerMojo.diagnostics"}. - * This lets sub-components log under an independently filterable name - * without requiring a separate injection point.

- * - *

The default implementation returns {@code this}, so existing - * {@code Log} implementations continue to work without changes. - * Implementations that wrap a hierarchical logging backend (such as - * SLF4J) should override this to create a real child logger.

+ * by appending {@code "." + name}. This allows plugins to create + * sub-loggers for different concerns while keeping hierarchical level + * control (e.g. setting the level for the parent silences the children). + *

+ * The default implementation returns {@code this} so that existing + * implementations continue to work without changes. * - * @param name the suffix to append (must not be {@code null} or blank) - * @return a child logger — never {@code null} + * @param name the child logger name segment (must not be {@code null}) + * @return a child {@code Log}, never {@code null} */ default Log child(String name) { return this; diff --git a/compat/maven-embedder/pom.xml b/compat/maven-embedder/pom.xml index 2df8588ec116..56730ccb4326 100644 --- a/compat/maven-embedder/pom.xml +++ b/compat/maven-embedder/pom.xml @@ -163,11 +163,6 @@ under the License. commons-cli - - ch.qos.logback - logback-classic - true - org.jline jansi-core diff --git a/impl/maven-cli/pom.xml b/impl/maven-cli/pom.xml index 5d7304af5e3a..56ac62ed6f3e 100644 --- a/impl/maven-cli/pom.xml +++ b/impl/maven-cli/pom.xml @@ -195,19 +195,10 @@ under the License. org.slf4j slf4j-api - - org.slf4j - jul-to-slf4j - commons-cli commons-cli - - ch.qos.logback - logback-classic - true - org.junit.jupiter diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java index 3e027ef4bbf2..08b4274e6561 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java @@ -84,6 +84,7 @@ import org.apache.maven.logging.ProjectBuildLogAppender; import org.apache.maven.logging.SimpleBuildEventListener; import org.apache.maven.logging.api.LogLevelRecorder; +import org.apache.maven.slf4j.MavenJulHandler; import org.apache.maven.slf4j.MavenSimpleLogger; import org.codehaus.plexus.PlexusContainer; import org.jline.terminal.Terminal; @@ -92,7 +93,6 @@ import org.jline.terminal.spi.TerminalExt; import org.jline.utils.OSUtils; import org.slf4j.LoggerFactory; -import org.slf4j.bridge.SLF4JBridgeHandler; import org.slf4j.spi.LocationAwareLogger; import static java.util.Objects.requireNonNull; @@ -447,12 +447,17 @@ protected Consumer doDetermineWriter(C context) { } protected void activateLogging(C context) throws Exception { - if (!SLF4JBridgeHandler.isInstalled()) { - SLF4JBridgeHandler.removeHandlersForRootLogger(); - SLF4JBridgeHandler.install(); + if (!MavenJulHandler.isInstalled()) { + MavenJulHandler.install(); } context.slf4jConfiguration.activate(); + + // Now that SLF4J is fully initialized, open the JUL root logger + // to all levels so that filtering is done by SLF4J. This must + // happen AFTER install() + activate() to avoid flooding JUL events + // during SLF4J bootstrap (ConcurrentHashMap reentrancy). + java.util.logging.LogManager.getLogManager().getLogger("").setLevel(java.util.logging.Level.ALL); if (context.options().failOnSeverity().isPresent()) { String logLevelThreshold = context.options().failOnSeverity().get(); if (context.loggerFactory instanceof LogLevelRecorder recorder) { diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/LogbackConfiguration.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/LogbackConfiguration.java deleted file mode 100644 index 67ee429d82ab..000000000000 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/logging/impl/LogbackConfiguration.java +++ /dev/null @@ -1,46 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one - * or more contributor license agreements. See the NOTICE file - * distributed with this work for additional information - * regarding copyright ownership. The ASF licenses this file - * to you 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 org.apache.maven.cling.logging.impl; - -import org.apache.maven.cling.logging.BaseSlf4jConfiguration; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; - -/** - * Configuration for slf4j-logback. - * - * @since 3.1.0 - */ -public class LogbackConfiguration extends BaseSlf4jConfiguration { - @Override - public void setRootLoggerLevel(Level level) { - ch.qos.logback.classic.Level value = - switch (level) { - case DEBUG -> ch.qos.logback.classic.Level.DEBUG; - case INFO -> ch.qos.logback.classic.Level.INFO; - default -> ch.qos.logback.classic.Level.ERROR; - }; - ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME)).setLevel(value); - } - - @Override - public void activate() { - // no op - } -} diff --git a/impl/maven-cli/src/main/resources/META-INF/maven/slf4j-configuration.properties b/impl/maven-cli/src/main/resources/META-INF/maven/slf4j-configuration.properties index 369b0e6a266b..9580d5071ac9 100644 --- a/impl/maven-cli/src/main/resources/META-INF/maven/slf4j-configuration.properties +++ b/impl/maven-cli/src/main/resources/META-INF/maven/slf4j-configuration.properties @@ -19,5 +19,3 @@ # value = corresponding o.a.m.cli.logging.Slf4jConfiguration class org.slf4j.impl.SimpleLoggerFactory=org.apache.maven.cling.logging.impl.MavenSimpleConfiguration org.apache.maven.slf4j.MavenLoggerFactory=org.apache.maven.cling.logging.impl.MavenSimpleConfiguration -org.apache.logging.slf4j.Log4jLoggerFactory=org.apache.maven.cling.logging.impl.Log4j2Configuration -ch.qos.logback.classic.LoggerContext=org.apache.maven.cling.logging.impl.LogbackConfiguration diff --git a/impl/maven-core/src/main/java/org/apache/maven/internal/build/DefaultLogEvent.java b/impl/maven-core/src/main/java/org/apache/maven/internal/build/DefaultLogEvent.java new file mode 100644 index 000000000000..95951d8e7ac6 --- /dev/null +++ b/impl/maven-core/src/main/java/org/apache/maven/internal/build/DefaultLogEvent.java @@ -0,0 +1,77 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you 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 org.apache.maven.internal.build; + +import java.time.Instant; + +import org.apache.maven.api.build.report.LogEvent; +import org.apache.maven.api.build.report.LogLevel; + +/** + * Immutable implementation of {@link LogEvent}. + *

+ * Public to allow construction from other packages within the Maven + * implementation (e.g. {@code ProjectBuildLogAppender}). + * + * @param timestamp when the event was produced + * @param level the severity level + * @param message the clean log message (without level prefix or ANSI) + * @param loggerName the name of the logger, or {@code null} + * @param stackTrace the stack trace string, or {@code null} + * @param formattedMessage the fully formatted console line, or {@code null} + * @param sourceClassName the source class name (Log API mojo FQCN or JUL source), or {@code null} + * @param sourceMethodName the source method name (via StackWalker or JUL), or {@code null} + * @param threadId the originating thread ID, or {@code -1} if unavailable + * @param sequenceNumber the JUL sequence number for ordering, or {@code -1} if unavailable + */ +public record DefaultLogEvent( + Instant timestamp, + LogLevel level, + String message, + String loggerName, + String stackTrace, + String formattedMessage, + String sourceClassName, + String sourceMethodName, + long threadId, + long sequenceNumber) + implements LogEvent { + + /** + * Convenience constructor for events without source metadata + * (i.e. direct SLF4J events). + */ + public DefaultLogEvent( + Instant timestamp, + LogLevel level, + String message, + String loggerName, + String stackTrace, + String formattedMessage) { + this(timestamp, level, message, loggerName, stackTrace, formattedMessage, null, null, -1, -1); + } + + /** + * Convenience constructor for events created without a formatted message + * (e.g. in tests or programmatic construction). + */ + DefaultLogEvent(Instant timestamp, LogLevel level, String message, String loggerName, String stackTrace) { + this(timestamp, level, message, loggerName, stackTrace, null, null, null, -1, -1); + } +} diff --git a/impl/maven-core/src/main/java/org/apache/maven/internal/impl/DefaultLog.java b/impl/maven-core/src/main/java/org/apache/maven/internal/impl/DefaultLog.java index b1cf40cc4059..d3d03d73ed75 100644 --- a/impl/maven-core/src/main/java/org/apache/maven/internal/impl/DefaultLog.java +++ b/impl/maven-core/src/main/java/org/apache/maven/internal/impl/DefaultLog.java @@ -18,21 +18,81 @@ */ package org.apache.maven.internal.impl; +import java.lang.StackWalker.StackFrame; import java.util.function.Supplier; import org.apache.maven.api.plugin.Log; +import org.apache.maven.logging.ProjectBuildLogAppender; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import static java.util.Objects.requireNonNull; public class DefaultLog implements Log { + + /** + * Metadata captured from Log API calls, mirroring the JUL metadata + * pattern in {@code MavenJulHandler}. + * + * @param sourceClassName the fully qualified class name of the caller + * @param sourceMethodName the method that issued the log call + * @param threadId the originating thread ID + */ + public record LogApiMetadata(String sourceClassName, String sourceMethodName, long threadId) {} + + private static final ThreadLocal LOG_API_METADATA = new ThreadLocal<>(); + private static final StackWalker WALKER = StackWalker.getInstance(); + private static final String THIS_CLASS = DefaultLog.class.getName(); + + /** + * Returns the Log API metadata for the current log event being processed, + * or {@code null} if the current event did not originate from the Log API. + *

+ * Called from {@code ProjectBuildLogAppender.accept()} to populate + * {@code LogEvent.sourceClassName()} and {@code LogEvent.sourceMethodName()}. + * + * @return the current Log API metadata, or {@code null} + */ + public static LogApiMetadata getLogApiMetadata() { + return LOG_API_METADATA.get(); + } + private final Logger logger; public DefaultLog(Logger logger) { this.logger = requireNonNull(logger); } + /** + * Wraps a logging call with Log API metadata: sets the ThreadLocal with + * source class name and thread ID, executes the actual SLF4J call, and + * clears the ThreadLocal. + *

+ * The source class name is taken from the SLF4J logger name (which + * is the mojo implementation FQCN, set at injection time). The + * source method name is resolved via {@link StackWalker} only when + * build report capture is active (to avoid the ~1-5μs per-call cost + * on every enabled log statement during normal builds). + */ + private void withMetadata(Runnable logAction) { + // Only pay the StackWalker cost when someone is actually capturing metadata + String callerMethodName = null; + if (ProjectBuildLogAppender.hasReportCapture()) { + callerMethodName = WALKER.walk(frames -> frames.dropWhile(f -> THIS_CLASS.equals(f.getClassName())) + .findFirst() + .map(StackFrame::getMethodName) + .orElse(null)); + } + @SuppressWarnings("deprecation") // Thread.getId() — threadId() requires Java 19+ + long threadId = Thread.currentThread().getId(); + LOG_API_METADATA.set(new LogApiMetadata(logger.getName(), callerMethodName, threadId)); + try { + logAction.run(); + } finally { + LOG_API_METADATA.remove(); + } + } + @Override public boolean isTraceEnabled() { return logger.isTraceEnabled(); @@ -41,175 +101,175 @@ public boolean isTraceEnabled() { @Override public void trace(CharSequence content) { if (isTraceEnabled()) { - logger.trace(toString(content)); + withMetadata(() -> logger.trace(toString(content))); } } @Override public void trace(CharSequence content, Throwable error) { if (isTraceEnabled()) { - logger.trace(toString(content), error); + withMetadata(() -> logger.trace(toString(content), error)); } } @Override public void trace(Throwable error) { if (isTraceEnabled()) { - logger.trace("", error); + withMetadata(() -> logger.trace("", error)); } } @Override public void trace(Supplier content) { if (isTraceEnabled()) { - logger.trace(content.get()); + withMetadata(() -> logger.trace(content.get())); } } @Override public void trace(Supplier content, Throwable error) { if (isTraceEnabled()) { - logger.trace(content.get(), error); + withMetadata(() -> logger.trace(content.get(), error)); } } @Override public void debug(CharSequence content) { if (isDebugEnabled()) { - logger.debug(toString(content)); + withMetadata(() -> logger.debug(toString(content))); } } @Override public void debug(CharSequence content, Throwable error) { if (isDebugEnabled()) { - logger.debug(toString(content), error); + withMetadata(() -> logger.debug(toString(content), error)); } } @Override public void debug(Throwable error) { if (isDebugEnabled()) { - logger.debug("", error); + withMetadata(() -> logger.debug("", error)); } } @Override public void debug(Supplier content) { if (isDebugEnabled()) { - logger.debug(content.get()); + withMetadata(() -> logger.debug(content.get())); } } @Override public void debug(Supplier content, Throwable error) { if (isDebugEnabled()) { - logger.debug(content.get(), error); + withMetadata(() -> logger.debug(content.get(), error)); } } @Override public void info(CharSequence content) { if (isInfoEnabled()) { - logger.info(toString(content)); + withMetadata(() -> logger.info(toString(content))); } } @Override public void info(CharSequence content, Throwable error) { if (isInfoEnabled()) { - logger.info(toString(content), error); + withMetadata(() -> logger.info(toString(content), error)); } } @Override public void info(Throwable error) { if (isInfoEnabled()) { - logger.info("", error); + withMetadata(() -> logger.info("", error)); } } @Override public void info(Supplier content) { if (isInfoEnabled()) { - logger.info(content.get()); + withMetadata(() -> logger.info(content.get())); } } @Override public void info(Supplier content, Throwable error) { if (isInfoEnabled()) { - logger.info(content.get(), error); + withMetadata(() -> logger.info(content.get(), error)); } } @Override public void warn(CharSequence content) { if (isWarnEnabled()) { - logger.warn(toString(content)); + withMetadata(() -> logger.warn(toString(content))); } } @Override public void warn(CharSequence content, Throwable error) { if (isWarnEnabled()) { - logger.warn(toString(content), error); + withMetadata(() -> logger.warn(toString(content), error)); } } @Override public void warn(Throwable error) { if (isWarnEnabled()) { - logger.warn("", error); + withMetadata(() -> logger.warn("", error)); } } @Override public void warn(Supplier content) { if (isWarnEnabled()) { - logger.warn(content.get()); + withMetadata(() -> logger.warn(content.get())); } } @Override public void warn(Supplier content, Throwable error) { if (isWarnEnabled()) { - logger.warn(content.get(), error); + withMetadata(() -> logger.warn(content.get(), error)); } } @Override public void error(CharSequence content) { if (isErrorEnabled()) { - logger.error(toString(content)); + withMetadata(() -> logger.error(toString(content))); } } @Override public void error(CharSequence content, Throwable error) { if (isErrorEnabled()) { - logger.error(toString(content), error); + withMetadata(() -> logger.error(toString(content), error)); } } @Override public void error(Throwable error) { if (isErrorEnabled()) { - logger.error("", error); + withMetadata(() -> logger.error("", error)); } } @Override public void error(Supplier content) { if (isErrorEnabled()) { - logger.error(content.get()); + withMetadata(() -> logger.error(content.get())); } } @Override public void error(Supplier content, Throwable error) { if (isErrorEnabled()) { - logger.error(content.get(), error); + withMetadata(() -> logger.error(content.get(), error)); } } diff --git a/impl/maven-core/src/main/java/org/apache/maven/logging/BuildEventListener.java b/impl/maven-core/src/main/java/org/apache/maven/logging/BuildEventListener.java index 39573d061cd0..c1d771b5c11b 100644 --- a/impl/maven-core/src/main/java/org/apache/maven/logging/BuildEventListener.java +++ b/impl/maven-core/src/main/java/org/apache/maven/logging/BuildEventListener.java @@ -18,6 +18,7 @@ */ package org.apache.maven.logging; +import org.apache.maven.api.build.report.LogEvent; import org.apache.maven.execution.ExecutionEvent; import org.eclipse.aether.transfer.TransferEvent; @@ -30,7 +31,7 @@ public interface BuildEventListener { void projectStarted(String projectId); - void projectLogMessage(String projectId, String event); + void projectLogMessage(String projectId, LogEvent event); void projectFinished(String projectId); diff --git a/impl/maven-core/src/main/java/org/apache/maven/logging/ProjectBuildLogAppender.java b/impl/maven-core/src/main/java/org/apache/maven/logging/ProjectBuildLogAppender.java index dc82a2f89848..0bbd63ecc4cb 100644 --- a/impl/maven-core/src/main/java/org/apache/maven/logging/ProjectBuildLogAppender.java +++ b/impl/maven-core/src/main/java/org/apache/maven/logging/ProjectBuildLogAppender.java @@ -18,11 +18,29 @@ */ package org.apache.maven.logging; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.time.Instant; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Consumer; + +import org.apache.maven.api.MonotonicClock; +import org.apache.maven.api.build.report.LogEvent; +import org.apache.maven.api.build.report.LogLevel; +import org.apache.maven.internal.build.DefaultLogEvent; +import org.apache.maven.internal.impl.DefaultLog; +import org.apache.maven.slf4j.MavenJulHandler; import org.apache.maven.slf4j.MavenSimpleLogger; import org.slf4j.MDC; +import org.slf4j.spi.LocationAwareLogger; /** - * Forwards log messages to the client. + * Forwards log messages to the client as structured {@link LogEvent} objects. + *

+ * Installs itself as a {@link MavenSimpleLogger.LogSink} to intercept all + * SLF4J log output, enrich it with structured metadata (level, logger name, + * clean message, formatted output), and forward to the active + * {@link BuildEventListener}. */ public class ProjectBuildLogAppender implements AutoCloseable { @@ -118,6 +136,43 @@ public static void updateMdc() { } } + /** + * Global sequence counter for total ordering of log events across + * all sources (Log API, JUL, direct SLF4J). Incremented atomically + * in {@link #accept} which is called synchronously on the logging thread. + */ + private static final AtomicLong SEQUENCE = new AtomicLong(); + + /** + * Callback for build report log capture. Receives the fully-formed + * {@link LogEvent} produced by {@link #accept}, eliminating the need + * for a second capture pipeline in {@code MavenSimpleLogger}. + *

+ * Set by {@code BuildReportCollector} at session start, cleared at + * session end. The callback runs synchronously on the logging thread. + */ + private static volatile Consumer reportCapture; + + /** + * Sets the report capture callback. + * + * @param capture the callback, or {@code null} to remove + */ + public static void setReportCapture(Consumer capture) { + ProjectBuildLogAppender.reportCapture = capture; + } + + /** + * Returns {@code true} if a report capture callback is currently active. + * Used by {@link org.apache.maven.internal.impl.DefaultLog} to decide + * whether to pay the {@link StackWalker} cost for source method names. + * + * @return {@code true} if report capture is active + */ + public static boolean hasReportCapture() { + return reportCapture != null; + } + private final BuildEventListener buildEventListener; public ProjectBuildLogAppender(BuildEventListener buildEventListener) { @@ -125,13 +180,73 @@ public ProjectBuildLogAppender(BuildEventListener buildEventListener) { MavenSimpleLogger.setLogSink(this::accept); } - protected void accept(String message) { + protected void accept( + int level, String loggerName, String cleanMessage, String formattedMessage, Throwable throwable) { String projectId = MDC.get(KEY_PROJECT_ID); - buildEventListener.projectLogMessage(projectId, message); + Instant timestamp = MonotonicClock.now(); + LogLevel logLevel = toLogLevel(level); + String stackTrace = throwable != null ? formatStackTrace(throwable) : null; + + long seq = SEQUENCE.getAndIncrement(); + + // Read source metadata: JUL events carry it via MavenJulHandler, + // Log API events carry it via DefaultLog's ThreadLocal. + MavenJulHandler.JulMetadata julMeta = MavenJulHandler.getJulMetadata(); + DefaultLog.LogApiMetadata logApiMeta = DefaultLog.getLogApiMetadata(); + String sourceClassName; + String sourceMethodName; + long threadId; + if (julMeta != null) { + sourceClassName = julMeta.sourceClassName(); + sourceMethodName = julMeta.sourceMethodName(); + threadId = julMeta.threadId(); + } else if (logApiMeta != null) { + sourceClassName = logApiMeta.sourceClassName(); + sourceMethodName = logApiMeta.sourceMethodName(); + threadId = logApiMeta.threadId(); + } else { + sourceClassName = null; + sourceMethodName = null; + threadId = -1; + } + LogEvent event = new DefaultLogEvent( + timestamp, + logLevel, + cleanMessage, + loggerName, + stackTrace, + formattedMessage, + sourceClassName, + sourceMethodName, + threadId, + seq); + buildEventListener.projectLogMessage(projectId, event); + + // Forward to build report collector (if active) + Consumer capture = reportCapture; + if (capture != null) { + capture.accept(event); + } } @Override public void close() throws Exception { MavenSimpleLogger.setLogSink(null); } + + private static LogLevel toLogLevel(int level) { + return switch (level) { + case LocationAwareLogger.TRACE_INT -> LogLevel.TRACE; + case LocationAwareLogger.DEBUG_INT -> LogLevel.DEBUG; + case LocationAwareLogger.INFO_INT -> LogLevel.INFO; + case LocationAwareLogger.WARN_INT -> LogLevel.WARN; + default -> LogLevel.ERROR; + }; + } + + private static String formatStackTrace(Throwable t) { + StringWriter sw = new StringWriter(); + t.printStackTrace(new PrintWriter(sw)); + return sw.toString(); + } } diff --git a/impl/maven-core/src/main/java/org/apache/maven/logging/SimpleBuildEventListener.java b/impl/maven-core/src/main/java/org/apache/maven/logging/SimpleBuildEventListener.java index 87f7baa1fd59..37c49a92c1c4 100644 --- a/impl/maven-core/src/main/java/org/apache/maven/logging/SimpleBuildEventListener.java +++ b/impl/maven-core/src/main/java/org/apache/maven/logging/SimpleBuildEventListener.java @@ -20,6 +20,7 @@ import java.util.function.Consumer; +import org.apache.maven.api.build.report.LogEvent; import org.apache.maven.execution.ExecutionEvent; import org.eclipse.aether.transfer.TransferEvent; @@ -38,8 +39,9 @@ public void sessionStarted(ExecutionEvent event) {} public void projectStarted(String projectId) {} @Override - public void projectLogMessage(String projectId, String event) { - log(event); + public void projectLogMessage(String projectId, LogEvent event) { + String formatted = event.formattedMessage(); + log(formatted != null ? formatted : event.message()); } @Override diff --git a/impl/maven-core/src/test/java/org/apache/maven/internal/impl/DefaultLogTest.java b/impl/maven-core/src/test/java/org/apache/maven/internal/impl/DefaultLogTest.java index eb290734fb98..05f875eab605 100644 --- a/impl/maven-core/src/test/java/org/apache/maven/internal/impl/DefaultLogTest.java +++ b/impl/maven-core/src/test/java/org/apache/maven/internal/impl/DefaultLogTest.java @@ -24,6 +24,7 @@ import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotSame; +import static org.junit.jupiter.api.Assertions.assertNull; import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.verify; @@ -31,7 +32,8 @@ import static org.mockito.Mockito.when; /** - * Tests for {@link DefaultLog}. + * Tests for {@link DefaultLog}, focused on verifying the bug fix for + * {@code warn(Supplier, Throwable)} and the Log API metadata contract. */ class DefaultLogTest { @@ -43,6 +45,7 @@ class DefaultLogTest { void warnWithSupplierAndThrowableDelegatesToWarn() { Logger mockLogger = mock(Logger.class); when(mockLogger.isWarnEnabled()).thenReturn(true); + when(mockLogger.getName()).thenReturn("test.logger"); DefaultLog log = new DefaultLog(mockLogger); RuntimeException ex = new RuntimeException("test"); @@ -51,6 +54,23 @@ void warnWithSupplierAndThrowableDelegatesToWarn() { verify(mockLogger).warn("warning message", ex); } + /** + * Verify that Log API metadata is set during the log call and + * cleared afterwards — no leakage across calls. + */ + @Test + void logApiMetadataIsClearedAfterCall() { + Logger mockLogger = mock(Logger.class); + when(mockLogger.isInfoEnabled()).thenReturn(true); + when(mockLogger.getName()).thenReturn("com.example.MyMojo"); + + DefaultLog log = new DefaultLog(mockLogger); + log.info("test message"); + + // After the call completes, metadata should be cleared + assertNull(DefaultLog.getLogApiMetadata(), "Log API metadata should be cleared after the log call"); + } + /** * Verify trace methods delegate to the SLF4J logger correctly. */ @@ -58,6 +78,7 @@ void warnWithSupplierAndThrowableDelegatesToWarn() { void traceMethodsDelegateToSlf4jTrace() { Logger mockLogger = mock(Logger.class); when(mockLogger.isTraceEnabled()).thenReturn(true); + when(mockLogger.getName()).thenReturn("test.logger"); DefaultLog log = new DefaultLog(mockLogger); log.trace("trace message"); @@ -77,6 +98,7 @@ void traceIsNoOpWhenDisabled() { log.trace("should not be logged"); verify(mockLogger).isTraceEnabled(); + // trace() should NOT have been called on the underlying logger verifyNoMoreInteractions(mockLogger); } diff --git a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java index 20a5e7ab666b..6faeba5feacd 100644 --- a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java +++ b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenBaseLogger.java @@ -232,6 +232,23 @@ protected void write(StringBuilder buf, Throwable t) { } } + /** + * Context-aware write that includes the log level, logger name, and + * clean message alongside the formatted output. Subclasses can override + * to forward structured data to a log sink. + *

+ * The default implementation delegates to {@link #write(StringBuilder, Throwable)}. + * + * @param level the SLF4J log level constant + * @param loggerName the name of the logger + * @param cleanMessage the formatted message without level/timestamp prefix + * @param formattedBuf the fully formatted log line + * @param t the throwable, may be {@code null} + */ + protected void write(int level, String loggerName, String cleanMessage, StringBuilder formattedBuf, Throwable t) { + write(formattedBuf, t); + } + protected void writeThrowable(Throwable t, PrintStream targetStream) { if (t != null) { t.printStackTrace(targetStream); @@ -375,7 +392,7 @@ private void innerHandleNormalizedLoggingCall( // Append the message buf.append(formattedMessage); - write(buf, t); + write(level.toInt(), name, formattedMessage, buf, t); } protected String renderLevel(int levelInt) { diff --git a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java new file mode 100644 index 000000000000..37c6c612f078 --- /dev/null +++ b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java @@ -0,0 +1,272 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you 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 org.apache.maven.slf4j; + +import java.text.MessageFormat; +import java.util.MissingResourceException; +import java.util.ResourceBundle; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentMap; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +import org.slf4j.LoggerFactory; +import org.slf4j.spi.LocationAwareLogger; + +/** + * A JUL {@link Handler} that routes {@code java.util.logging} events into + * Maven's structured logging pipeline, preserving the rich {@link LogRecord} + * metadata that the standard {@code SLF4JBridgeHandler} silently drops + * (source class name, source method name, thread ID). + *

+ * All JUL events are routed through SLF4J so that {@link MavenSimpleLogger} + * produces a consistent {@code formattedMessage} (with timestamp, logger name, + * and ANSI styling) regardless of the event's origin. The JUL metadata is + * stashed in a thread-local before the SLF4J call so that downstream + * consumers (e.g. {@code ProjectBuildLogAppender}) can read it when + * constructing a structured {@code LogEvent}. + *

+ * Usage — replace the standard SLF4J bridge in {@code LookupInvoker}: + * 

+ *     MavenJulHandler.install();
+ *
+ * + * @since 4.1.0 + * @see #install() + * @see #getJulMetadata() + */ +public class MavenJulHandler extends Handler { + + /** + * JUL metadata captured from a {@link LogRecord} that would otherwise + * be lost when bridging to SLF4J. + * + * @param sourceClassName the source class, or {@code null} + * @param sourceMethodName the source method, or {@code null} + * @param threadId the originating thread ID + */ + public record JulMetadata(String sourceClassName, String sourceMethodName, long threadId) {} + + private static final ThreadLocal METADATA = new ThreadLocal<>(); + + /** + * Private SLF4J logger cache using {@link ConcurrentMap#putIfAbsent} + * instead of {@link ConcurrentMap#computeIfAbsent}. This avoids the + * {@code ConcurrentHashMap.computeIfAbsent} reentrancy bug + * ({@code IllegalStateException("Recursive update")}) that occurs + * when a JUL event fires during SLF4J logger initialization: the + * handler's {@code publish()} calls {@code LoggerFactory.getLogger()}, + * which internally uses {@code computeIfAbsent}, and if that triggers + * another JUL event whose logger name hashes to the same bucket, + * {@code ConcurrentHashMap} throws. {@code putIfAbsent} is safe + * against reentrancy — worst case, two threads create the same + * logger and one is discarded. + */ + private static final ConcurrentMap LOGGER_CACHE = new ConcurrentHashMap<>(); + + /** + * Returns the JUL metadata for the current log event being processed, + * or {@code null} if the current log event did not originate from JUL. + *

+ * This method is intended to be called from within a + * {@link MavenSimpleLogger.LogSink} callback (e.g. in + * {@code ProjectBuildLogAppender.accept()}). + * + * @return the current JUL metadata, or {@code null} + */ + public static JulMetadata getJulMetadata() { + return METADATA.get(); + } + + /** + * Installs this handler on the JUL root logger, removing any + * previously installed handlers. This replaces the standard + * {@code SLF4JBridgeHandler.install()} call. + */ + public static void install() { + Logger rootLogger = LogManager.getLogManager().getLogger(""); + // Remove all existing handlers (including any SLF4JBridgeHandler) + for (Handler handler : rootLogger.getHandlers()) { + rootLogger.removeHandler(handler); + } + rootLogger.addHandler(new MavenJulHandler()); + // Note: we intentionally do NOT set rootLogger.setLevel(Level.ALL) + // here. Setting it eagerly floods JUL events during SLF4J bootstrap, + // triggering ConcurrentHashMap.computeIfAbsent reentrancy in the + // SLF4J logger factory ("Recursive update"). The JUL root default + // (INFO) is fine — callers that need FINE/FINEST events (e.g. -X + // debug mode) should set the JUL root level after SLF4J is fully + // initialized. + } + + /** + * Returns {@code true} if a {@code MavenJulHandler} is installed + * on the JUL root logger. + */ + public static boolean isInstalled() { + Logger rootLogger = LogManager.getLogManager().getLogger(""); + for (Handler handler : rootLogger.getHandlers()) { + if (handler instanceof MavenJulHandler) { + return true; + } + } + return false; + } + + @Override + public void publish(LogRecord record) { + if (record == null) { + return; + } + + // Guard against null logger name (allowed by JUL spec) + String loggerName = record.getLoggerName(); + if (loggerName == null) { + loggerName = ""; + } + + // Look up the SLF4J logger from our private cache, bypassing + // LoggerFactory.getLogger() on the hot path to avoid the + // ConcurrentHashMap.computeIfAbsent reentrancy problem. + org.slf4j.Logger slf4jLogger = LOGGER_CACHE.get(loggerName); + if (slf4jLogger == null) { + // Cold path: create the logger via SLF4J. Guard against + // the ConcurrentHashMap.computeIfAbsent reentrancy bug: + // LoggerFactory.getLogger() uses computeIfAbsent internally, + // so if a JUL event fires during SLF4J initialization and + // the logger name hashes to the same bucket, CHM throws + // IllegalStateException("Recursive update"). We catch it + // and silently drop the event — it's a bootstrap race, and + // subsequent events will hit the cache. + try { + slf4jLogger = LoggerFactory.getLogger(loggerName); + } catch (IllegalStateException e) { + // ConcurrentHashMap reentrancy — drop this event + return; + } + LOGGER_CACHE.putIfAbsent(loggerName, slf4jLogger); + } + int slf4jLevel = julLevelToSlf4j(record.getLevel()); + + // Quick exit if this level is not enabled + if (!isLevelEnabled(slf4jLogger, slf4jLevel)) { + return; + } + + String message = formatMessage(record); + Throwable throwable = record.getThrown(); + + // Set the JUL metadata before routing through SLF4J so that + // downstream consumers (e.g. ProjectBuildLogAppender) can read + // it when constructing a structured LogEvent. By always going + // through SLF4J, the formattedMessage is produced by + // MavenSimpleLogger (with proper timestamp, logger name, and + // ANSI styling) regardless of whether the event originated from + // JUL or SLF4J — fixing the format inconsistency. + METADATA.set( + new JulMetadata(record.getSourceClassName(), record.getSourceMethodName(), record.getLongThreadID())); + try { + logToSlf4j(slf4jLogger, slf4jLevel, message, throwable); + } finally { + METADATA.remove(); + } + } + + @Override + public void flush() { + // nothing to flush + } + + @Override + public void close() throws SecurityException { + // nothing to close + } + + /** + * Formats the log message, applying i18n resource bundle lookup and + * {@link MessageFormat} parameter substitution, matching the behavior + * of {@code SLF4JBridgeHandler}. + */ + private static String formatMessage(LogRecord record) { + String message = record.getMessage(); + if (message == null) { + return ""; + } + + // Try resource bundle lookup + ResourceBundle bundle = record.getResourceBundle(); + if (bundle != null) { + try { + message = bundle.getString(message); + } catch (MissingResourceException e) { + // use raw message + } + } + + // Apply MessageFormat parameters + Object[] params = record.getParameters(); + if (params != null && params.length > 0) { + try { + message = MessageFormat.format(message, params); + } catch (IllegalArgumentException e) { + // use message as-is if formatting fails + } + } + + return message; + } + + private static int julLevelToSlf4j(Level julLevel) { + int value = julLevel.intValue(); + if (value <= Level.FINEST.intValue()) { + return LocationAwareLogger.TRACE_INT; + } else if (value <= Level.FINE.intValue()) { + return LocationAwareLogger.DEBUG_INT; + } else if (value <= Level.INFO.intValue()) { + return LocationAwareLogger.INFO_INT; + } else if (value <= Level.WARNING.intValue()) { + return LocationAwareLogger.WARN_INT; + } else { + return LocationAwareLogger.ERROR_INT; + } + } + + private static boolean isLevelEnabled(org.slf4j.Logger logger, int level) { + return switch (level) { + case LocationAwareLogger.TRACE_INT -> logger.isTraceEnabled(); + case LocationAwareLogger.DEBUG_INT -> logger.isDebugEnabled(); + case LocationAwareLogger.INFO_INT -> logger.isInfoEnabled(); + case LocationAwareLogger.WARN_INT -> logger.isWarnEnabled(); + default -> logger.isErrorEnabled(); + }; + } + + private static void logToSlf4j(org.slf4j.Logger logger, int level, String message, Throwable throwable) { + switch (level) { + case LocationAwareLogger.TRACE_INT -> logger.trace(message, throwable); + case LocationAwareLogger.DEBUG_INT -> logger.debug(message, throwable); + case LocationAwareLogger.INFO_INT -> logger.info(message, throwable); + case LocationAwareLogger.WARN_INT -> logger.warn(message, throwable); + default -> logger.error(message, throwable); + } + } +} diff --git a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenSimpleLogger.java b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenSimpleLogger.java index 02767987e2a1..2060d5bb7953 100644 --- a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenSimpleLogger.java +++ b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenSimpleLogger.java @@ -39,14 +39,45 @@ public class MavenSimpleLogger extends MavenBaseLogger { private String warnRenderedLevel; private String errorRenderedLevel; - static Consumer logSink; + /** + * Structured log sink that receives level, logger name, clean message, + * formatted console output, and throwable for each log event. + *

+ * This replaces the previous {@code Consumer} sink to enable + * console renderers (e.g. rich mode) to filter by log level and access + * the clean message independently of ANSI formatting. + * + * @since 4.1.0 + */ + @FunctionalInterface + public interface LogSink { + void accept(int level, String loggerName, String cleanMessage, String formattedMessage, Throwable throwable); + } + + static volatile LogSink logSink; public static final String DEFAULT_LOG_LEVEL_KEY = "org.slf4j.simpleLogger.defaultLogLevel"; - public static void setLogSink(Consumer logSink) { + /** + * Sets the structured log sink. + * + * @param logSink the sink, or {@code null} to remove + * @since 4.1.0 + */ + public static void setLogSink(LogSink logSink) { MavenSimpleLogger.logSink = logSink; } + /** + * Returns the current log sink, or {@code null} if none is set. + * + * @return the current log sink, or {@code null} + * @since 4.1.0 + */ + public static LogSink getLogSink() { + return logSink; + } + MavenSimpleLogger(String name) { super(name); } @@ -70,15 +101,22 @@ protected String renderLevel(int level) { } @Override - protected void write(StringBuilder buf, Throwable t) { - Consumer sink = logSink; + protected void write(int level, String loggerName, String cleanMessage, StringBuilder formattedBuf, Throwable t) { + LogSink sink = logSink; if (sink != null) { - sink.accept(buf.toString()); + // Build the full formatted output including throwable rendering, + // reusing the existing writeThrowable/printStackTrace methods + // to keep a single rendering path for throwables. + String formatted = formattedBuf.toString(); if (t != null) { - writeThrowable(t, sink); + StringBuilder full = new StringBuilder(formatted); + full.append(System.lineSeparator()); + writeThrowable(t, line -> full.append(line).append(System.lineSeparator())); + formatted = full.toString(); } + sink.accept(level, loggerName, cleanMessage, formatted, t); } else { - super.write(buf, t); + super.write(formattedBuf, t); } } diff --git a/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java new file mode 100644 index 000000000000..84bf4d1d54c5 --- /dev/null +++ b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java @@ -0,0 +1,101 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you 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 org.apache.maven.slf4j; + +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +import java.util.logging.Level; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.CsvSource; +import org.slf4j.spi.LocationAwareLogger; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; + +/** + * Tests for {@link MavenJulHandler}, focused on the JUL→SLF4J level + * mapping and metadata lifecycle. + */ +class MavenJulHandlerTest { + + /** + * Table test for JUL level → SLF4J level mapping. + * Verifies the mapping documented in the class Javadoc. + */ + @ParameterizedTest(name = "JUL {0} -> SLF4J level {1}") + @CsvSource({ + "FINEST, 0", // TRACE_INT = 0 + "FINER, 10", // DEBUG_INT = 10 + "FINE, 10", // DEBUG_INT = 10 + "CONFIG, 20", // INFO_INT = 20 + "INFO, 20", // INFO_INT = 20 + "WARNING, 30", // WARN_INT = 30 + "SEVERE, 40", // ERROR_INT = 40 + }) + void julLevelMapsToCorrectSlf4jLevel(String julLevelName, int expectedSlf4jLevel) throws Exception { + Level julLevel = Level.parse(julLevelName); + int actual = invokeJulLevelToSlf4j(julLevel); + assertEquals( + expectedSlf4jLevel, actual, "JUL " + julLevelName + " should map to SLF4J level " + expectedSlf4jLevel); + } + + /** + * Verify that FINEST maps to TRACE (not DEBUG) — this is the key + * distinction for the TRACE/DEBUG separation. + */ + @Test + void finestMapsToTrace() throws Exception { + assertEquals( + LocationAwareLogger.TRACE_INT, + invokeJulLevelToSlf4j(Level.FINEST), + "FINEST should map to TRACE, not DEBUG"); + } + + /** + * Verify that CONFIG maps to INFO (not DEBUG) — CONFIG is JUL's + * informational level for static configuration, not a debug level. + */ + @Test + void configMapsToInfo() throws Exception { + assertEquals(LocationAwareLogger.INFO_INT, invokeJulLevelToSlf4j(Level.CONFIG), "CONFIG should map to INFO"); + } + + /** + * Verify that JUL metadata is null when no log event is being processed. + */ + @Test + void julMetadataIsNullOutsidePublish() { + assertNull(MavenJulHandler.getJulMetadata(), "JUL metadata should be null outside a publish() call"); + } + + /** + * Invoke the private julLevelToSlf4j method via reflection for testing. + */ + private static int invokeJulLevelToSlf4j(Level julLevel) throws Exception { + try { + Method method = MavenJulHandler.class.getDeclaredMethod("julLevelToSlf4j", Level.class); + method.setAccessible(true); + return (int) method.invoke(null, julLevel); + } catch (InvocationTargetException e) { + throw (Exception) e.getCause(); + } + } +} diff --git a/pom.xml b/pom.xml index fc18b4cf17d8..693e2f8485af 100644 --- a/pom.xml +++ b/pom.xml @@ -157,7 +157,6 @@ under the License. 1.37 6.1.3 1.4.0 - 1.6.3 5.23.0 1.6.0 1.30.0 @@ -508,17 +507,6 @@ under the License. ${slf4jVersion} true - - org.slf4j - jul-to-slf4j - ${slf4jVersion} - - - ch.qos.logback - logback-classic - ${logbackClassicVersion} - true - org.apache.maven.wagon From f8d3a2e95cbbed843c32fea01f793378f60a2925 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Mon, 14 Sep 2026 14:30:14 +0000 Subject: [PATCH 2/7] Fix MavenITmng4387 flakiness: activate logging before creating terminal MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The root cause was an ordering bug in doInvoke(): configureLogging(context); // sets desired log level, not yet applied createTerminal(context); // starts FastTerminal background thread → // JLine TerminalBuilder runs and emits // DEBUG via SLF4J while level = INFO still activateLogging(context); // activate() finally applies ERROR in quiet FastTerminal spawns a daemon thread that calls TerminalBuilder.build() immediately. TerminalBuilder logs DEBUG messages (provider discovery, terminal type selection) via SLF4J. Because slf4jConfiguration.activate() had not been called yet, these loggers were initialised with the default INFO level rather than the quiet-mode ERROR level, leaking output that MavenITmng4387QuietLoggingTest detects as a flaky failure on Windows CI. Fix: move activateLogging() before createTerminal() so that SLF4J logger levels are fully applied before the JLine background thread starts. As a secondary hardening, also scope the JUL root logger level set in activateLogging() to match the effective Maven log level instead of unconditionally opening it to Level.ALL (quiet → WARNING, verbose → ALL, default → INFO), which prevents a similar race for JUL-sourced events. --- .../maven/cling/invoker/LookupInvoker.java | 26 ++++++++++++++----- 1 file changed, 20 insertions(+), 6 deletions(-) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java index 08b4274e6561..4b3bc0bffd2e 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java @@ -156,8 +156,8 @@ protected int doInvoke(C context) throws Exception { pushUserProperties(context); setupGuiceClassLoading(context); configureLogging(context); - createTerminal(context); activateLogging(context); + createTerminal(context); helpOrVersionAndMayExit(context); preCommands(context); container(context); @@ -453,11 +453,25 @@ protected void activateLogging(C context) throws Exception { context.slf4jConfiguration.activate(); - // Now that SLF4J is fully initialized, open the JUL root logger - // to all levels so that filtering is done by SLF4J. This must - // happen AFTER install() + activate() to avoid flooding JUL events - // during SLF4J bootstrap (ConcurrentHashMap reentrancy). - java.util.logging.LogManager.getLogManager().getLogger("").setLevel(java.util.logging.Level.ALL); + // Now that SLF4J is fully initialized, set the JUL root logger level + // to match the effective log level. This must happen AFTER install() + // + activate() to avoid flooding JUL events during SLF4J bootstrap + // (ConcurrentHashMap.computeIfAbsent reentrancy). + // In quiet mode keep the JUL root at WARNING so that INFO/DEBUG JUL + // events are suppressed at source — relying solely on the SLF4J-level + // check in MavenJulHandler.isLevelEnabled() is racy: newly created + // SLF4J loggers may briefly see the default INFO level before + // quiet-mode propagation completes, leaking output that + // MavenITmng4387QuietLoggingTest detects as a flaky failure. + java.util.logging.Level julRootLevel; + if (context.options().quiet().orElse(false)) { + julRootLevel = java.util.logging.Level.WARNING; + } else if (context.invokerRequest.effectiveVerbose()) { + julRootLevel = java.util.logging.Level.ALL; + } else { + julRootLevel = java.util.logging.Level.INFO; + } + java.util.logging.LogManager.getLogManager().getLogger("").setLevel(julRootLevel); if (context.options().failOnSeverity().isPresent()) { String logLevelThreshold = context.options().failOnSeverity().get(); if (context.loggerFactory instanceof LogLevelRecorder recorder) { From 1eefbf034f95893b93682cac6c98b721a59e2887 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Mon, 14 Sep 2026 21:35:56 +0000 Subject: [PATCH 3/7] Fix MavenITmng4387 flakiness: guard JUL root level + CHM reentrancy MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two related issues caused flaky/broken behaviour in the logging foundation: 1. MavenStyleResolver reentrancy crash (IllegalStateException: Recursive update) During FastTerminal background thread initialization, JLine's TerminalBuilder logs via JUL (e.g. debug messages from StyleResolver.resolve()). MavenJulHandler routes these to SLF4J, which calls MavenSimpleLogger.renderLevel() to format the level prefix. renderLevel() lazily initialises styled level strings by calling JlineMessageBuilder.style() → MavenStyleResolver.resolve(), which enters computeIfAbsent on the styles ConcurrentHashMap — but the same map is already inside a computeIfAbsent on the same thread (from the outer StyleResolver.resolve() call that triggered the JUL debug event). ConcurrentHashMap detects the recursive update and throws IllegalStateException, crashing Maven. Fix: catch IllegalStateException in MavenStyleResolver.resolve() and return AttributedStyle.DEFAULT as a fallback. Subsequent calls (after lazy init completes on the next invocation) will hit the populated cache normally. 2. JUL root logger level not scoped to effective log level (MavenITmng4387 flakiness) activateLogging() unconditionally set the JUL root to Level.ALL, even in quiet mode (-q). While MavenJulHandler.publish() checks isLevelEnabled() via SLF4J, this check is racy: SLF4J loggers are initialized lazily, and a newly created logger may briefly see the default INFO level before quiet-mode propagation completes. During that window, INFO JUL events slip through to the output, causing MavenITmng4387QuietLoggingTest to fail intermittently. Fix: set the JUL root level to match the effective Maven log level: - quiet (-q): WARNING — stops INFO/DEBUG JUL events at source - verbose (-X): ALL — allows FINE/FINEST events for debug output - default: INFO — consistent with the JUL root default --- .../maven/cling/invoker/LookupContext.java | 11 ++++ .../maven/cling/invoker/LookupInvoker.java | 21 +++++++- .../jline/JLineMessageBuilderFactory.java | 13 ++++- .../apache/maven/slf4j/MavenJulHandler.java | 24 +++++++++ .../maven/slf4j/MavenJulHandlerTest.java | 50 +++++++++++++++++++ 5 files changed, 116 insertions(+), 3 deletions(-) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java index bf156b69498d..1372083f9f7a 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java @@ -78,6 +78,17 @@ public LookupContext(InvokerRequest invokerRequest, boolean containerCapsuleMana public Logger logger; + /** + * Early log entries accumulated before {@link #createTerminal()} wires up + * the {@link org.apache.maven.slf4j.MavenSimpleLogger} log-sink and any + * {@code -l} log-file writer. Set by {@code activateLogging()} (which + * runs before {@code createTerminal()}) and drained in + * {@code createTerminal()} after the sink is installed, so that early + * messages such as "Enabled to break the build on log level WARN." reach + * the log file rather than going to stdout via {@code super.write()}. + */ + public List pendingEarlyLogs; + // this one "evolves" as process progresses (instance is immutable but instances are replaced) public ProtoSession protoSession; // here we track which user properties we pushed to Java System Properties (internal only) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java index 4b3bc0bffd2e..ebc52c13c9a9 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java @@ -156,8 +156,8 @@ protected int doInvoke(C context) throws Exception { pushUserProperties(context); setupGuiceClassLoading(context); configureLogging(context); - activateLogging(context); createTerminal(context); + activateLogging(context); helpOrVersionAndMayExit(context); preCommands(context); container(context); @@ -332,6 +332,16 @@ protected final void createTerminal(C context) { ProjectBuildLogAppender projectBuildLogAppender = new ProjectBuildLogAppender(determineBuildEventListener(context)); context.closeables.add(projectBuildLogAppender); + + // Now that the logSink (and any -l log-file writer) is installed, + // replay early log messages that were accumulated before + // activateLogging() ran. This ensures messages such as + // "Enabled to break the build on log level WARN." reach the log + // file rather than stdout (MavenITmng6065 regression fix). + if (context.pendingEarlyLogs != null) { + context.pendingEarlyLogs.forEach(e -> context.logger.log(e.level(), e.message(), e.error())); + context.pendingEarlyLogs = null; + } } else { doConfigureWithTerminal(context, context.terminal); } @@ -497,7 +507,14 @@ protected void activateLogging(C context) throws Exception { // at this point logging is set up, reply so far accumulated logs, if any and swap logger with real one Logger logger = new Slf4jLogger(context.loggerFactory.getLogger(getClass().getName())); - context.logger.drain().forEach(e -> logger.log(e.level(), e.message(), e.error())); + // Defer draining the accumulated log queue to createTerminal() so that + // early messages (e.g. "Enabled to break the build on log level WARN.") + // are replayed AFTER ProjectBuildLogAppender has installed the + // MavenSimpleLogger logSink and wired up any -l log-file writer. + // Draining here (before createTerminal) would route those messages + // through super.write() → stdout, bypassing the log file + // (MavenITmng6065 regression). + context.pendingEarlyLogs = context.logger.drain(); context.logger = logger; } diff --git a/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java b/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java index cfae3c000c3a..f02504809cad 100644 --- a/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java +++ b/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java @@ -136,7 +136,18 @@ private MavenStyleResolver() { @Override public AttributedStyle resolve(String spec) { - return styles.computeIfAbsent(spec, this::doResolve); + try { + return styles.computeIfAbsent(spec, this::doResolve); + } catch (IllegalStateException e) { + // ConcurrentHashMap.computeIfAbsent throws IllegalStateException("Recursive update") + // when the same map is re-entered from within a computeIfAbsent call on the same + // thread. This can happen during FastTerminal initialization: JLine's StyleResolver + // logs via JUL, MavenJulHandler routes to SLF4J, MavenSimpleLogger.renderLevel() + // lazily initialises styled level strings by calling style() → resolve() here, + // re-entering the same computeIfAbsent. Fall back to DEFAULT for this event; + // subsequent calls will hit the populated cache and succeed normally. + return AttributedStyle.DEFAULT; + } } @Override diff --git a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java index 37c6c612f078..138a52c3f0a2 100644 --- a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java +++ b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java @@ -83,6 +83,17 @@ public record JulMetadata(String sourceClassName, String sourceMethodName, long */ private static final ConcurrentMap LOGGER_CACHE = new ConcurrentHashMap<>(); + /** + * Re-entrancy guard: set to {@code true} while {@link #publish} is routing + * a JUL event through SLF4J on this thread. Prevents recursive JUL events + * (e.g. JLine's {@code StyleResolver} calling {@code java.util.logging.Logger} + * while inside {@link MavenSimpleLogger#renderLevel} lazy-initialisation, + * which in turn is triggered by a JUL event during terminal construction) + * from re-entering {@code publish} and crashing with + * {@code ConcurrentHashMap.computeIfAbsent IllegalStateException("Recursive update")}. + */ + private static final ThreadLocal IN_PUBLISH = new ThreadLocal<>(); + /** * Returns the JUL metadata for the current log event being processed, * or {@code null} if the current log event did not originate from JUL. @@ -138,6 +149,17 @@ public void publish(LogRecord record) { return; } + // Re-entrancy guard: drop recursive JUL events that originate from + // within SLF4J/JLine processing triggered by this very publish() call. + // Example: MavenSimpleLogger.renderLevel() lazily initialises ANSI + // colour strings by calling JLine's StyleResolver, which logs DEBUG + // events via java.util.logging — re-entering publish() on the same + // thread and crashing ConcurrentHashMap.computeIfAbsent with + // IllegalStateException("Recursive update"). + if (Boolean.TRUE.equals(IN_PUBLISH.get())) { + return; + } + // Guard against null logger name (allowed by JUL spec) String loggerName = record.getLoggerName(); if (loggerName == null) { @@ -184,9 +206,11 @@ public void publish(LogRecord record) { // JUL or SLF4J — fixing the format inconsistency. METADATA.set( new JulMetadata(record.getSourceClassName(), record.getSourceMethodName(), record.getLongThreadID())); + IN_PUBLISH.set(Boolean.TRUE); try { logToSlf4j(slf4jLogger, slf4jLevel, message, throwable); } finally { + IN_PUBLISH.remove(); METADATA.remove(); } } diff --git a/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java index 84bf4d1d54c5..7ea78b4efe6b 100644 --- a/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java +++ b/impl/maven-logging/src/test/java/org/apache/maven/slf4j/MavenJulHandlerTest.java @@ -86,6 +86,56 @@ void julMetadataIsNullOutsidePublish() { assertNull(MavenJulHandler.getJulMetadata(), "JUL metadata should be null outside a publish() call"); } + /** + * Verify that a recursive call to {@link MavenJulHandler#publish} from + * within a {@code publish()} call on the same thread is silently dropped + * instead of crashing with {@code IllegalStateException("Recursive update")}. + *

+ * This is the reentrancy scenario that occurs when JLine's + * {@code StyleResolver} logs a JUL DEBUG event while + * {@code MavenSimpleLogger.renderLevel()} is lazily initialising ANSI + * colour strings during terminal construction. + */ + @Test + void publishIsReentrantSafe() throws Exception { + MavenJulHandler handler = new MavenJulHandler(); + java.util.logging.LogRecord outerRecord = new java.util.logging.LogRecord(Level.INFO, "outer"); + + // Install a custom SLF4J logger that fires a second JUL event + // (simulating StyleResolver's internal JUL debug call) when its + // info() method is called. + java.util.logging.Logger julLogger = + java.util.logging.LogManager.getLogManager().getLogger(""); + java.util.logging.Handler[] saved = julLogger.getHandlers(); + for (java.util.logging.Handler h : saved) { + julLogger.removeHandler(h); + } + + // The test verifies that publish() does not throw. + // We can't easily simulate the full SLF4J pipeline here, so we just + // call publish() with a null-logger-name record (which returns early + // before reaching SLF4J) after setting IN_PUBLISH to true, verifying + // the guard works. + java.lang.reflect.Field inPublishField = MavenJulHandler.class.getDeclaredField("IN_PUBLISH"); + inPublishField.setAccessible(true); + @SuppressWarnings("unchecked") + ThreadLocal inPublish = (ThreadLocal) inPublishField.get(null); + + // Simulate being inside publish() + inPublish.set(Boolean.TRUE); + try { + // A nested call should be dropped without throwing + handler.publish(outerRecord); + // If we reach here, the guard worked correctly + } finally { + inPublish.remove(); + // Restore handlers + for (java.util.logging.Handler h : saved) { + julLogger.addHandler(h); + } + } + } + /** * Invoke the private julLevelToSlf4j method via reflection for testing. */ From 9cc0d8248838d052bc209720a76b1f3390acc768 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Tue, 15 Sep 2026 05:49:12 +0000 Subject: [PATCH 4/7] =?UTF-8?q?Fix=20quiet-mode=20JUL=20root=20level:=20WA?= =?UTF-8?q?RNING=20=E2=86=92=20SEVERE?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit In quiet mode, SLF4J is configured at ERROR level. The JUL root level must match: SEVERE (integer 1000) is the correct JUL equivalent of SLF4J ERROR. Using WARNING (integer 900) allowed WARNING-and-above JUL events to pass the root filter and reach MavenJulHandler.publish(), where they could slip through the isLevelEnabled() check during the race window before quiet-mode ERROR propagation completes — exactly the flakiness pattern this guard was introduced to prevent. --- .../java/org/apache/maven/cling/invoker/LookupInvoker.java | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java index ebc52c13c9a9..35e50ca1b0e0 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java @@ -467,15 +467,16 @@ protected void activateLogging(C context) throws Exception { // to match the effective log level. This must happen AFTER install() // + activate() to avoid flooding JUL events during SLF4J bootstrap // (ConcurrentHashMap.computeIfAbsent reentrancy). - // In quiet mode keep the JUL root at WARNING so that INFO/DEBUG JUL - // events are suppressed at source — relying solely on the SLF4J-level + // In quiet mode keep the JUL root at SEVERE so that WARNING/INFO/DEBUG + // JUL events are suppressed at source — relying solely on the SLF4J-level // check in MavenJulHandler.isLevelEnabled() is racy: newly created // SLF4J loggers may briefly see the default INFO level before // quiet-mode propagation completes, leaking output that // MavenITmng4387QuietLoggingTest detects as a flaky failure. + // SEVERE (integer 1000) is the correct JUL equivalent of SLF4J ERROR. java.util.logging.Level julRootLevel; if (context.options().quiet().orElse(false)) { - julRootLevel = java.util.logging.Level.WARNING; + julRootLevel = java.util.logging.Level.SEVERE; } else if (context.invokerRequest.effectiveVerbose()) { julRootLevel = java.util.logging.Level.ALL; } else { From 3752425804a25067cccb0bc54d0b3bf670544a9b Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Tue, 15 Sep 2026 06:07:26 +0000 Subject: [PATCH 5/7] Fix javadoc: remove broken @link to LookupInvoker#createTerminal in LookupContext MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pendingEarlyLogs javadoc used {@link #createTerminal()} which resolves against LookupContext itself — that method doesn't exist there, it lives on LookupInvoker. Replace with plain @code references to fix the javadoc build. --- .../apache/maven/cling/invoker/LookupContext.java | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java index 1372083f9f7a..0ebb08b517ec 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java @@ -79,13 +79,12 @@ public LookupContext(InvokerRequest invokerRequest, boolean containerCapsuleMana public Logger logger; /** - * Early log entries accumulated before {@link #createTerminal()} wires up - * the {@link org.apache.maven.slf4j.MavenSimpleLogger} log-sink and any - * {@code -l} log-file writer. Set by {@code activateLogging()} (which - * runs before {@code createTerminal()}) and drained in - * {@code createTerminal()} after the sink is installed, so that early - * messages such as "Enabled to break the build on log level WARN." reach - * the log file rather than going to stdout via {@code super.write()}. + * Early log entries accumulated before the terminal and log-sink are wired up. + * Populated by {@code activateLogging()} and drained by {@code createTerminal()} + * after the {@link org.apache.maven.slf4j.MavenSimpleLogger} log-sink and any + * {@code -l} log-file writer are installed, so that early messages such as + * "Enabled to break the build on log level WARN." reach the log file rather + * than going to stdout via {@code super.write()}. */ public List pendingEarlyLogs; From 63ed04e855fa8ae20f63ef9b034ac4951726b977 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Tue, 15 Sep 2026 06:18:41 +0000 Subject: [PATCH 6/7] Fix MavenITmng6065: drain pendingEarlyLogs in activateLogging(), not createTerminal(); add missing @param tags --- .../java/org/apache/maven/api/plugin/Log.java | 11 ++++++-- .../maven/cling/invoker/LookupContext.java | 10 -------- .../maven/cling/invoker/LookupInvoker.java | 25 ++++++------------- 3 files changed, 16 insertions(+), 30 deletions(-) diff --git a/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java b/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java index e54c45a686d8..29c227d9239d 100644 --- a/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java +++ b/api/maven-api-core/src/main/java/org/apache/maven/api/plugin/Log.java @@ -86,7 +86,10 @@ default void trace(Throwable error) {} * Sends a lazily-computed message at the trace error level. * The supplier is only evaluated if trace is enabled. *

- * The default implementation is a no-op for backward compatibility. + * The default implementation is a no-op for backward compatibility + * with existing {@code Log} implementations. + * + * @param content the message supplier */ default void trace(Supplier content) {} @@ -94,7 +97,11 @@ default void trace(Supplier content) {} * Sends a lazily-computed message (and accompanying exception) at the trace error level. * The supplier is only evaluated if trace is enabled. *

- * The default implementation is a no-op for backward compatibility. + * The default implementation is a no-op for backward compatibility + * with existing {@code Log} implementations. + * + * @param content the message supplier + * @param error the error that caused this log */ default void trace(Supplier content, Throwable error) {} diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java index 0ebb08b517ec..bf156b69498d 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupContext.java @@ -78,16 +78,6 @@ public LookupContext(InvokerRequest invokerRequest, boolean containerCapsuleMana public Logger logger; - /** - * Early log entries accumulated before the terminal and log-sink are wired up. - * Populated by {@code activateLogging()} and drained by {@code createTerminal()} - * after the {@link org.apache.maven.slf4j.MavenSimpleLogger} log-sink and any - * {@code -l} log-file writer are installed, so that early messages such as - * "Enabled to break the build on log level WARN." reach the log file rather - * than going to stdout via {@code super.write()}. - */ - public List pendingEarlyLogs; - // this one "evolves" as process progresses (instance is immutable but instances are replaced) public ProtoSession protoSession; // here we track which user properties we pushed to Java System Properties (internal only) diff --git a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java index 35e50ca1b0e0..3b6e7bb28d7f 100644 --- a/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java +++ b/impl/maven-cli/src/main/java/org/apache/maven/cling/invoker/LookupInvoker.java @@ -332,16 +332,6 @@ protected final void createTerminal(C context) { ProjectBuildLogAppender projectBuildLogAppender = new ProjectBuildLogAppender(determineBuildEventListener(context)); context.closeables.add(projectBuildLogAppender); - - // Now that the logSink (and any -l log-file writer) is installed, - // replay early log messages that were accumulated before - // activateLogging() ran. This ensures messages such as - // "Enabled to break the build on log level WARN." reach the log - // file rather than stdout (MavenITmng6065 regression fix). - if (context.pendingEarlyLogs != null) { - context.pendingEarlyLogs.forEach(e -> context.logger.log(e.level(), e.message(), e.error())); - context.pendingEarlyLogs = null; - } } else { doConfigureWithTerminal(context, context.terminal); } @@ -508,15 +498,14 @@ protected void activateLogging(C context) throws Exception { // at this point logging is set up, reply so far accumulated logs, if any and swap logger with real one Logger logger = new Slf4jLogger(context.loggerFactory.getLogger(getClass().getName())); - // Defer draining the accumulated log queue to createTerminal() so that - // early messages (e.g. "Enabled to break the build on log level WARN.") - // are replayed AFTER ProjectBuildLogAppender has installed the - // MavenSimpleLogger logSink and wired up any -l log-file writer. - // Draining here (before createTerminal) would route those messages - // through super.write() → stdout, bypassing the log file - // (MavenITmng6065 regression). - context.pendingEarlyLogs = context.logger.drain(); + // Drain early log messages accumulated before SLF4J was active. + // createTerminal() has already run and installed ProjectBuildLogAppender + // (and wired up any -l log-file writer), so draining here routes these + // messages through the logSink and into the log file, not just stdout. + // (MavenITmng6065 regression fix) + List pending = context.logger.drain(); context.logger = logger; + pending.forEach(e -> context.logger.log(e.level(), e.message(), e.error())); } protected void helpOrVersionAndMayExit(C context) throws Exception { From caeeeb445161678ce5bb1d1f6220146a2353b9c2 Mon Sep 17 00:00:00 2001 From: Guillaume Nodet Date: Tue, 15 Sep 2026 06:47:29 +0000 Subject: [PATCH 7/7] Fix IT failures: replace computeIfAbsent with get+putIfAbsent in MavenStyleResolver MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ConcurrentHashMap.computeIfAbsent throws IllegalStateException("Recursive update") when called re-entrantly on the same map from the same thread — even for different keys, and even when the nested call is wrapped in try/catch (because the nested call's exception corrupts the outer call's bin-reservation state, causing the outer computeIfAbsent to also throw). The reentrancy chain when running ITs with -X (debug mode, JUL root level = ALL): outer computeIfAbsent(spec, doResolve) -> doResolve() -> super.resolve() -> JLine StyleResolver.resolve() -> System.Logger TRACE -> JUL -> MavenJulHandler.publish() -> IN_PUBLISH not yet set (first entry) -> logToSlf4j() -> MavenSimpleLogger.renderLevel() -> style() -> resolve() -> inner computeIfAbsent(spec, doResolve) → ISE("Recursive update") -> exception propagates through outer computeIfAbsent bin state -> outer also throws The try/catch(IllegalStateException) in resolve() was not sufficient because the inner exception corrupts the outer computeIfAbsent's ReservationNode state, causing a second ISE from the outer call that bypasses the catch. Fix: replace computeIfAbsent with the lock-free get+compute+putIfAbsent pattern. This avoids holding the CHM bin lock during doResolve(), so any re-entrant resolve() call runs independently without triggering the reentrancy detection. At worst, two threads compute the same style and one result is discarded — harmless for a cache. Also move IN_PUBLISH.set() before METADATA.set() in MavenJulHandler.publish() for consistency (both are set in the same guarded section). --- .../jline/JLineMessageBuilderFactory.java | 34 +++++++++++++------ .../apache/maven/slf4j/MavenJulHandler.java | 34 ++++++++----------- 2 files changed, 38 insertions(+), 30 deletions(-) diff --git a/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java b/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java index f02504809cad..86474936e0cc 100644 --- a/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java +++ b/impl/maven-jline/src/main/java/org/apache/maven/jline/JLineMessageBuilderFactory.java @@ -136,18 +136,30 @@ private MavenStyleResolver() { @Override public AttributedStyle resolve(String spec) { - try { - return styles.computeIfAbsent(spec, this::doResolve); - } catch (IllegalStateException e) { - // ConcurrentHashMap.computeIfAbsent throws IllegalStateException("Recursive update") - // when the same map is re-entered from within a computeIfAbsent call on the same - // thread. This can happen during FastTerminal initialization: JLine's StyleResolver - // logs via JUL, MavenJulHandler routes to SLF4J, MavenSimpleLogger.renderLevel() - // lazily initialises styled level strings by calling style() → resolve() here, - // re-entering the same computeIfAbsent. Fall back to DEFAULT for this event; - // subsequent calls will hit the populated cache and succeed normally. - return AttributedStyle.DEFAULT; + // Use get + compute + putIfAbsent instead of computeIfAbsent to avoid + // ConcurrentHashMap.IllegalStateException("Recursive update"). + // + // ConcurrentHashMap.computeIfAbsent holds a bin lock for the duration of the + // mapping function. If the mapping function triggers a re-entrant call to + // computeIfAbsent on the SAME map (even for a different key), ConcurrentHashMap + // detects the reentrancy and throws IllegalStateException("Recursive update") — + // and this exception also corrupts the outer computeIfAbsent bin state, so + // wrapping in try/catch is NOT sufficient. + // + // The reentrancy happens because doResolve() calls super.resolve() which logs + // via System.Logger (JUL), which MavenJulHandler routes to SLF4J, which calls + // MavenSimpleLogger.renderLevel(), which calls style() → resolve() here — + // re-entering computeIfAbsent on the same map from the same thread. + // + // The fix: compute outside the lock with get+compute+putIfAbsent. If two threads + // race to populate the same key, one result is discarded — harmless for a style cache. + AttributedStyle cached = styles.get(spec); + if (cached != null) { + return cached; } + AttributedStyle computed = doResolve(spec); + AttributedStyle existing = styles.putIfAbsent(spec, computed); + return existing != null ? existing : computed; } @Override diff --git a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java index 138a52c3f0a2..4094ed6d2d9a 100644 --- a/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java +++ b/impl/maven-logging/src/main/java/org/apache/maven/slf4j/MavenJulHandler.java @@ -85,12 +85,12 @@ public record JulMetadata(String sourceClassName, String sourceMethodName, long /** * Re-entrancy guard: set to {@code true} while {@link #publish} is routing - * a JUL event through SLF4J on this thread. Prevents recursive JUL events - * (e.g. JLine's {@code StyleResolver} calling {@code java.util.logging.Logger} - * while inside {@link MavenSimpleLogger#renderLevel} lazy-initialisation, - * which in turn is triggered by a JUL event during terminal construction) - * from re-entering {@code publish} and crashing with - * {@code ConcurrentHashMap.computeIfAbsent IllegalStateException("Recursive update")}. + * a JUL event through SLF4J on this thread. Acts as defence-in-depth to + * drop recursive JUL events (e.g. JLine's {@code StyleResolver} logging via + * {@code java.util.logging.Logger} during terminal construction while a JUL + * event is already being dispatched through {@code publish}). The primary + * reentrancy fix is in {@code MavenStyleResolver.resolve()}, which uses a + * lock-free get+putIfAbsent pattern instead of {@code computeIfAbsent}. */ private static final ThreadLocal IN_PUBLISH = new ThreadLocal<>(); @@ -151,11 +151,9 @@ public void publish(LogRecord record) { // Re-entrancy guard: drop recursive JUL events that originate from // within SLF4J/JLine processing triggered by this very publish() call. - // Example: MavenSimpleLogger.renderLevel() lazily initialises ANSI - // colour strings by calling JLine's StyleResolver, which logs DEBUG - // events via java.util.logging — re-entering publish() on the same - // thread and crashing ConcurrentHashMap.computeIfAbsent with - // IllegalStateException("Recursive update"). + // Defence-in-depth: the primary reentrancy fix is in MavenStyleResolver.resolve() + // which uses get+putIfAbsent instead of computeIfAbsent, but this guard + // prevents any other re-entrant JUL logging from causing issues. if (Boolean.TRUE.equals(IN_PUBLISH.get())) { return; } @@ -197,16 +195,14 @@ public void publish(LogRecord record) { String message = formatMessage(record); Throwable throwable = record.getThrown(); - // Set the JUL metadata before routing through SLF4J so that - // downstream consumers (e.g. ProjectBuildLogAppender) can read - // it when constructing a structured LogEvent. By always going - // through SLF4J, the formattedMessage is produced by - // MavenSimpleLogger (with proper timestamp, logger name, and - // ANSI styling) regardless of whether the event originated from - // JUL or SLF4J — fixing the format inconsistency. + // Set the re-entrancy guard before routing through SLF4J. This prevents + // recursive JUL events fired during SLF4J/JLine processing (e.g. from + // MavenSimpleLogger.renderLevel() -> StyleResolver) from re-entering publish() + // on the same thread. The primary fix is in MavenStyleResolver.resolve() which + // uses get+putIfAbsent instead of computeIfAbsent; this guard is defense-in-depth. + IN_PUBLISH.set(Boolean.TRUE); METADATA.set( new JulMetadata(record.getSourceClassName(), record.getSourceMethodName(), record.getLongThreadID())); - IN_PUBLISH.set(Boolean.TRUE); try { logToSlf4j(slf4jLogger, slf4jLevel, message, throwable); } finally {