gnodet-bot commented on code in PR #13860: URL: https://github.com/apache/maven/pull/13860#discussion_r4493855056
########## compat/maven-embedder/src/test/java/org/apache/maven/cli/MavenCliLoggingTest.java: ########## @@ -0,0 +1,407 @@ +/* + * 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.cli; + +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.lang.reflect.Field; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.FutureTask; +import java.util.concurrent.atomic.AtomicBoolean; + +import org.apache.maven.cling.logging.Slf4jConfiguration; +import org.apache.maven.cling.logging.Slf4jConfigurationFactory; +import org.apache.maven.jline.FastTerminal; +import org.apache.maven.jline.MessageUtils; +import org.apache.maven.slf4j.MavenBaseLogger; +import org.jline.terminal.Terminal; +import org.jline.terminal.spi.TerminalExt; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.junit.jupiter.api.parallel.Isolated; +import org.slf4j.LoggerFactory; + +import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.concurrent.TimeUnit.SECONDS; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.Mockito.RETURNS_DEEP_STUBS; +import static org.mockito.Mockito.mock; + +@Isolated("Changes JVM-wide streams, system properties, terminal state, and logging configuration") +class MavenCliLoggingTest { + + private PrintStream savedOut; + private Terminal savedTerminal; + private boolean savedColor; + + @BeforeEach + void setUp() throws Exception { + savedOut = System.out; + savedTerminal = getTerminalField(); + savedColor = getColorEnabled(); + // Null out the terminal so leftover FastTerminal threads from other tests cannot + // race with this test's stream setup via their consumer callbacks. + injectTerminal(null); + } + + @AfterEach + void tearDown() throws Exception { + System.setOut(savedOut); + injectTerminal(savedTerminal); + setColorEnabled(savedColor); + // Clear both properties and reactivate the logger so it writes to the restored + // System.err (the default). Always clear rather than restore: activateSlf4j() + // must run against a clean slate to reset the logger state correctly. + System.clearProperty(MavenBaseLogger.LEGACY_PREFIX + "logFile"); + System.clearProperty(MavenBaseLogger.LEGACY_PREFIX + "cacheOutputStream"); + activateSlf4j(); + } + + /** + * When color is explicitly forced ({@code -Dstyle.color=always}), {@code logging()} must NOT + * call {@code awaitTerminalInitialization()} before activating the logging configuration. + * The logger must therefore cache the stream that was active at activation time (the "early" + * stream), not the stream installed by the terminal consumer afterwards. + * <p> + * On master, {@code MavenSimpleLogger.configure()} renders ANSI-coloured level labels via + * {@code JLineMessageBuilderFactory}, which calls {@code terminal.getType()} and therefore + * always awaits terminal initialisation inside {@code activate()}. The key behavioral + * difference being tested is that with {@code color=always}, {@code config.init()} captures + * {@code System.out} <em>before</em> the terminal consumer runs (because + * {@code awaitTerminalInitialization()} is skipped before {@code activate()}). + * <p> + * This test uses a held-back {@link FastTerminal} instead of a {@code DumbTerminal}. The + * terminal build blocks until the test releases it. Since {@code logging()} with + * {@code color=always} does not call {@code awaitTerminalInitialization()} before + * {@code activate()}, the logger caches {@code earlyStream} in {@code config.init()}, then + * blocks inside {@code configure()} waiting for the terminal. When the test releases the + * terminal, the consumer swaps {@code System.out} to {@code terminalStream}, but the logger + * has already cached {@code earlyStream}. + */ + @Test + void withColorForcedLoggerCachesEarlyStream() throws Exception { + CountDownLatch buildingTerminal = new CountDownLatch(1); + CountDownLatch releaseTerminal = new CountDownLatch(1); + ByteArrayOutputStream earlyOutput = new ByteArrayOutputStream(); + ByteArrayOutputStream terminalOutput = new ByteArrayOutputStream(); + Thread loggingThread = null; + try (PrintStream earlyStream = new PrintStream(earlyOutput, true, UTF_8.name()); + PrintStream terminalStream = new PrintStream(terminalOutput, true, UTF_8.name())) { + System.setProperty(MavenBaseLogger.LEGACY_PREFIX + "cacheOutputStream", "true"); + System.setProperty(MavenBaseLogger.LEGACY_PREFIX + "logFile", "System.out"); + System.setOut(earlyStream); + activateSlf4j(); + + FastTerminal terminal = new FastTerminal( + () -> { + buildingTerminal.countDown(); + if (!releaseTerminal.await(10, SECONDS)) { + throw new IllegalStateException("Terminal installation was not released"); + } + return mock(TerminalExt.class, RETURNS_DEEP_STUBS); + }, + installed -> System.setOut(terminalStream)); + injectTerminal(terminal); + terminal.start(); + assertTrue(buildingTerminal.await(10, SECONDS), "FastTerminal build thread must start"); + + // Run logging() on a separate thread — it will block inside configure() when + // toAnsi() calls FastTerminal.getType() → getTerminal() → terminal.get(). + MavenCli cli = new MavenCli(); + CliRequest request = new CliRequest(new String[] {"-Dstyle.color=always"}, null); + cli.cli(request); + cli.properties(request); + FutureTask<Void> logging = new FutureTask<>(() -> { + cli.logging(request); + return null; + }); + loggingThread = new Thread(logging, "logging-initialization-test"); + loggingThread.setDaemon(true); + loggingThread.start(); + + // Wait until the logging thread is blocked on the terminal's CompletableFuture. + // At that point, config.init() has already captured earlyStream (it runs before + // configure() which is where the block occurs). + awaitThreadState(loggingThread, Thread.State.WAITING, 10_000); + + // Release the terminal — the consumer sets System.out=terminalStream, but the + // logger has already cached earlyStream in config.init(). + releaseTerminal.countDown(); + logging.get(10, SECONDS); + + // The logger must still write to earlyStream. + LoggerFactory.getLogger(MavenCliLoggingTest.class).warn("terminal-output-marker"); + assertTrue( + earlyOutput.toString(UTF_8.name()).contains("terminal-output-marker"), + "Logger must write to the stream that was active when logging() ran with -color=always"); + assertFalse( + terminalOutput.toString(UTF_8.name()).contains("terminal-output-marker"), + "Logger must not switch to the stream installed after logging() completed"); + } finally { + releaseTerminal.countDown(); + if (loggingThread != null) { + loggingThread.join(10_000); + } + } + } + + /** + * When {@code -l <logfile>} is used, {@code logging()} must call + * {@link MessageUtils#awaitTerminalInitialization()} before redirecting {@code System.out} + * to the log file. Without the await, the terminal's installed consumer (which may call + * {@code System.setOut}) could race with the log-file redirect, causing logs to leak to + * the console instead of the log file (see + * <a href="https://github.com/apache/maven/issues/12188";>#12188</a>). + * <p> + * This test verifies that the terminal consumer fires <em>before</em> {@code System.out} is + * redirected to the log file, so the consumer cannot overwrite the log-file redirect. + */ + @Test + void logFileBranchAwaitsTerminalBeforeRedirect(@TempDir Path tempDir) throws Exception { + PrintStream originalOut = System.out; + + Path logFile = tempDir.resolve("maven.log"); + Files.writeString(logFile, ""); + + CountDownLatch buildingTerminal = new CountDownLatch(1); + CountDownLatch releaseTerminal = new CountDownLatch(1); + // Set by the terminal consumer; true means the consumer fired before System.out was + // redirected to the log file — which is the correct behaviour: the consumer fires + // BEFORE the log redirect, so it cannot overwrite it. + AtomicBoolean consumerFiredBeforeRedirect = new AtomicBoolean(false); + Thread loggingThread = null; + try { + FastTerminal terminal = new FastTerminal( + () -> { + buildingTerminal.countDown(); + if (!releaseTerminal.await(10, SECONDS)) { + throw new IllegalStateException("Terminal installation was not released"); + } + return mock(TerminalExt.class, RETURNS_DEEP_STUBS); + }, + installed -> { + // The consumer fires as part of terminal.complete() inside the build thread. + // If awaitTerminalInitialization() was called, the consumer fires BEFORE + // logging() redirects System.out to the log file. We detect this by + // checking whether System.out is still the original stream at this point. + consumerFiredBeforeRedirect.set(System.out == originalOut); + }); + injectTerminal(terminal); + terminal.start(); + assertTrue(buildingTerminal.await(10, SECONDS), "FastTerminal build thread must start"); + + MavenCli cli = new MavenCli(); + CliRequest request = + new CliRequest(new String[] {"-l", logFile.toAbsolutePath().toString()}, null); + cli.cli(request); + cli.properties(request); + FutureTask<Void> logging = new FutureTask<>(() -> { + cli.logging(request); + return null; + }); + loggingThread = new Thread(logging, "logging-initialization-test"); + loggingThread.setDaemon(true); + loggingThread.start(); + + // Release the terminal; logging() will unblock from awaitTerminalInitialization(), + // the consumer fires, then the redirect happens. + releaseTerminal.countDown(); + logging.get(10, SECONDS); + + // The consumer must have fired before System.out was redirected to the log file. + assertTrue( + consumerFiredBeforeRedirect.get(), + "Terminal consumer must fire before System.out is redirected to the log file; " + + "if it fires after, it could overwrite the log-file redirect (#12188)"); + + // After logging() returns, System.out must be redirected to the log file (not original). + assertFalse( + System.out == originalOut, + "After logging() with -l, System.out must be redirected to the log file"); + } finally { + releaseTerminal.countDown(); + if (loggingThread != null) { + loggingThread.join(10_000); + } + // Close the PrintStream wrapping maven.log before System.out is restored. Review Comment: The comment says the stream is closed *before* `System.out` is restored, but the code does the opposite — `System.setOut(originalOut)` runs first (restores `System.out`), then `logStream.close()`. The functional logic is correct (closing the stream before the method returns is all `@TempDir` needs on Windows), but the comment describes the wrong ordering. Suggested fix: ```suggestion // Close the PrintStream wrapping maven.log so @TempDir can delete the temp directory on Windows. // An open FileOutputStream prevents directory deletion on Windows. ``` -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
