Use structured logging in the IPC server by efegokdemir · Pull Request #2157 · apache/maven-resolver

efegokdemir · 2026-09-23T11:02:50Z

Summary

Fixes #1989 by routing IpcServer diagnostics through SLF4J instead of writing directly to System.out.

Changes

Add an SLF4J logger to IpcServer.
Route debug, informational, and error messages through the logger.
Preserve throwable details for error diagnostics.

Testing

mvn -pl maven-resolver-named-locks-ipc -am -DskipITs -DskipTests=false -Dspotless.apply.skip=true -Dspotless.check.skip=true test — PASS (reactor build; all tests passed).
git diff --check — PASS.
Spotless formatting was not run because the repository configured Palantir formatter is incompatible with the available JDK 27 runtime; the source follows existing formatting and the build Checkstyle and RAT checks passed.

Notes

No overlapping open PR was found for issue Production error logging to System.out in IpcServer #1989 or the IpcServer logging change during the final duplicate check.
The commit is signed and includes the required DCO sign-off.
AI assistance was used to prepare this change; the submitter has reviewed the implementation and test results.

Signed-off-by: Efe Gökdemir <efe@rexcode.co.uk>

gnodet-bot

The intent is right — IpcServer should not be writing to System.out — but the implementation does not work in the normal (forked) execution mode and silently regresses diagnostic output.

Root cause: when IpcServer is forked as a subprocess (the default, non-NO_FORK path), the classpath passed by IpcClient is getJarPath(IpcClient.class) + getJarPath(IpcServer.class), which resolves to the single maven-resolver-named-locks-ipc-*.jar. slf4j-api is declared provided (not bundled) and slf4j-simple is test scope — so there is no SLF4J binding on the forked process classpath. SLF4J 2.x responds by printing "SLF4J(W): No SLF4J providers were found" to stderr (which ends up in the log file) and silently using a no-op logger. Every subsequent LOGGER.info() / LOGGER.error() call is dropped with no output.

See IpcClient.java:188:

String classpath = getJarPath(getClass()) + File.pathSeparator + getJarPath(IpcServer.class);

Before this PR, System.out.printf / t.printStackTrace(System.out) wrote to the log file because both stdout and stderr are redirected to logFile via ProcessBuilder.Redirect. After this PR, those writes are gone and nothing replaces them.

The fix must make SLF4J functional in the forked JVM. There are two approaches:

Bundle slf4j-simple in the jar (preferred for a self-contained forked server): add it to the Maven Shade/Assembly plugin, or change the classpath construction in IpcClient to include it at runtime.
Pass the host classpath to the forked process so the Maven runtime's SLF4J binding is inherited.
Keep System.out for the forked-subprocess code paths and only use SLF4J in the in-process (NO_FORK) path — guard on IpcServer.DEFAULT_NO_FORK or a flag.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

gnodet-bot · 2026-09-23T11:07:03Z

    private static void debug(String msg, Object... args) {
        if (DEBUG) {
-            System.out.printf("[ipc] [debug] " + msg + "\n", args);
+            LOGGER.debug(msg, args);


⚠️ No SLF4J binding in forked process — messages silently dropped.

When IpcServer is started as a subprocess (the default path), IpcClient passes only the maven-resolver-named-locks-ipc jar on the classpath (see IpcClient.java:188). slf4j-api is provided scope and slf4j-simple is test scope — neither is present in the forked JVM. SLF4J 2.x falls back to a no-op logger: this LOGGER.info() call produces no output. Before this PR, System.out.printf wrote to logFile via ProcessBuilder.Redirect.to(logFile.toFile()) — that output is now gone.

The same applies to LOGGER.debug() and LOGGER.error() below. The error() method previously printed a full stack trace via t.printStackTrace(System.out); that diagnostic is now silently lost.

Signed-off-by: Efe Gökdemir <efe@rexcode.co.uk>

efegokdemir · 2026-09-23T11:41:31Z

Addressed the review by keeping the original stdout/stderr diagnostics for the forked server process, whose isolated classpath has no SLF4J provider, while retaining SLF4J logging for in-process (NO_FORK) execution.

Validation on JDK 21:

mvn -pl maven-resolver-named-locks-ipc -am -DskipITs -DskipTests=false test — PASS (13 tests)
mvn -pl maven-resolver-named-locks-ipc -am -Prun-its verify — FAIL in the existing IPC integration setup with ByteChannelWrapper/forked-server classpath errors; no assertion failure points to this logging-only change.
git diff --check — PASS

The follow-up is commit 278d3be9c8e77467cc5edaabdc9910f0a7a2bea2.

gnodet-bot

The forkedProcess flag correctly solves the missing-SLF4J-binding problem raised in the previous review: main() sets it as its very first statement, so System.out is used throughout the forked-subprocess path, and slf4j-api is never loaded in that JVM. The lazy inline LoggerFactory.getLogger() calls (rather than a static field) are intentional and correct — a static field initializer would load LoggerFactory at class-load time and throw NoClassDefFoundError in the forked JVM where slf4j-api is absent. That design is sound.

One issue remains before this is ready.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

gnodet-bot · 2026-09-23T11:45:21Z

+        if (forkedProcess) {
+            System.out.printf("[ipc] [info] " + msg + "\n", args);
+        } else {
+            LoggerFactory.getLogger(IpcServer.class).info(msg, args);


⚠️ Printf-style format strings are not compatible with SLF4J's {} placeholder syntax.

The msg strings passed to the helper methods use printf format specifiers (%s, %d). For example:

info("IpcServer started at %s", getLocalAddress().toString()); info("New client connected (%d connected)", c); info("%d clients remained", c); debug("Created context %s", context.id); debug("Locking in context %s", context.id);

When these hit the !forkedProcess branch, SLF4J receives "IpcServer started at %s" with argument [address]. SLF4J only substitutes {} — it passes %s through literally. The result in the log is "IpcServer started at %s" with the address silently discarded. This affects all three new SLF4J call sites (debug, info, error).

All call-site format strings must be converted to SLF4J {} syntax at the same time as this change. Either update the call sites, or convert the helper methods to do the translation:

Suggested change

LoggerFactory.getLogger(IpcServer.class).info(msg, args);

LoggerFactory.getLogger(IpcServer.class).info(msg.replaceAll("%[sd]", "{}"), args);

Or, cleaner — convert all format strings at the call sites (e.g. "IpcServer started at {}", "New client connected ({} connected)") and drop the printf-style approach entirely.

efegokdemir · 2026-09-23T11:48:52Z

Follow-up commit 6f05a28dfe2ec7f52f472c7f1d8f6da049427e29 converts all SLF4J call-site placeholders from printf-style (%s/%d) to {}. Forked-process output is formatted separately for stdout, while in-process logging now receives native SLF4J placeholders.

Added IpcClientForkedTest to verify forked startup diagnostics remain in the redirected log.

Validation on JDK 21: mvn -pl maven-resolver-named-locks-ipc -am -DskipITs -DskipTests=false test — PASS (14 IPC tests; reactor BUILD SUCCESS); git diff upstream/master...HEAD --check — PASS.

gnodet-bot

Both previous findings are fully addressed by the latest two commits.

Review 1 (no SLF4J binding in forked process): The forkedProcess flag routes all diagnostics back to System.out in the forked JVM. Since slf4j-api is never loaded in the forked classpath, this avoids the NoClassDefFoundError entirely. ✓

Review 2 (%s/%d vs {} placeholder mismatch): All call-site format strings are now SLF4J {} syntax. The new format() helper translates {} → %s for the String.format path on System.out. Both log destinations now receive correctly formatted output. ✓

One issue with the new test.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

gnodet-bot · 2026-09-23T11:55:24Z

+class IpcClientForkedTest {
+
+    @Test
+    void forkedServerDiagnosticsAreWrittenToLog(@TempDir Path tempDir) throws Exception {


⚠️ Test hangs indefinitely if the forked server fails to start.

client.ensureInitialized() calls createClient(), which forks the IPC server JVM and blocks on future.get(5, TimeUnit.SECONDS) waiting for the server to connect back. If the fork fails silently (e.g. classpath resolution issue in CI, port conflict, OOM), future.get() will throw after 5 s — but the outer ensureInitialized() has no timeout guard and the JUnit test method has no @Timeout either. If something inside ensureInitialized() stalls outside the future.get() window (e.g. during lock acquisition), the test blocks the CI runner indefinitely.

Add a JUnit 5 @Timeout as a hard upper bound:

Suggested change

void forkedServerDiagnosticsAreWrittenToLog(@TempDir Path tempDir) throws Exception {

@Test

@org.junit.jupiter.api.Timeout(30)

void forkedServerDiagnosticsAreWrittenToLog(@TempDir Path tempDir) throws Exception {

And add the import at the top of the file alongside @Test:

import org.junit.jupiter.api.Timeout;

Then use @Timeout(30) without the fully-qualified name.

gnodet-bot

All three previous findings are addressed:

SLF4J binding in forked JVM → forkedProcess flag routes to System.out. ✓
%s/%d vs {} placeholders → format() helper + all call sites updated. ✓
@Timeout missing on test → @Timeout(10) added with import. ✓

Two issues remain.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

gnodet-bot · 2026-09-23T12:55:45Z

+        } finally {
+            if (client.initialized) {
+                client.stopServer();
+            }
+            client.close();


⚠️ Resource leak if stopServer() throws.

stopServer() wraps its failure in a RuntimeException and rethrows (see IpcClient.java:469). If it throws here, client.close() at line 66 is unreachable — the forked server process is never killed. In CI this leaks a lingering subprocess that may hold the socket address, causing subsequent test runs to fail.

Fix with a nested try:

Suggested change

} finally {

if (client.initialized) {

client.stopServer();

}

client.close();

} finally {

try {

if (client.initialized) {

client.stopServer();

}

} finally {

client.close();

}

gnodet-bot · 2026-09-23T12:55:46Z

 * @since 2.0.1
 */
 public class IpcServer {
+    private static volatile boolean forkedProcess;


⚠️ static volatile boolean forkedProcess is permanent — no reset path.

Once main() sets forkedProcess = true, it stays true for the lifetime of the JVM. In normal operation (forked subprocess) this is fine because that JVM exits. But if a future test ever calls IpcServer.main() in-process (e.g. to test the main() entry point directly), all subsequent in-process uses of IpcServer will silently use System.out instead of SLF4J — exactly the regression this PR is fixing.

The field should be package-private and reset when the server shuts down, or scoped so it doesn't bleed across test cases:

Suggested change

private static volatile boolean forkedProcess;

static volatile boolean forkedProcess;

(Package-private lets tests reset it with IpcServer.forkedProcess = false in @AfterEach if needed, without requiring a public API.)

gnodet-bot

Previous findings status:

SLF4J binding in forked JVM → forkedProcess flag routes to System.out. ✓
%s/%d vs {} placeholders → format() helper + all call sites updated. ✓
@Timeout missing on test → @Timeout(30) now set. ✓
forkedProcess permanent flag → reset in IpcServer.run() finally block; field made package-private for test access. ✓
IpcClient.close() try/finally → stopServer() now wrapped in try/finally so close(IOException) always executes on the production code path. ✓

One issue remains.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

gnodet-bot · 2026-09-23T15:26:32Z

+        } finally {
+            if (client.initialized) {
+                client.stopServer();
+            }
+            client.close();
+        }


⚠️ Resource leak if stopServer() throws — still not fixed.

The new commit added try/finally in the production IpcClient.close() path, but this test's finally block is unchanged. stopServer() wraps any failure in a RuntimeException and rethrows it (see IpcClient.java:471). If that happens here, client.close() at line 66 is never called — the forked server subprocess leaks and may hold the socket address, causing subsequent test runs in the same JVM to fail.

The fix is a nested try/finally:

Suggested change

} finally {

if (client.initialized) {

client.stopServer();

}

client.close();

}

} finally {

try {

if (client.initialized) {

client.stopServer();

}

} finally {

client.close();

}

}

gnodet-bot

All five previous findings are addressed by the latest two commits (4e7382cb and f6e89e10):

SLF4J binding in forked JVM → forkedProcess flag routes all diagnostics to System.out in the forked subprocess path. SLF4J is never loaded in that JVM. ✓
%s/%d vs {} placeholder mismatch → format() helper translates {} → %s for the System.out path; all call sites now use SLF4J {} syntax for both branches. ✓
@Timeout missing on test → @Timeout(30) is set with the import present. ✓
forkedProcess permanent flag → reset to false in IpcServer.run() finally block; field is package-private for test access. ✓
Resource leak if stopServer() throws (test and production) → both IpcClient.close() and the test finally block now use nested try/finally, so close() always executes even if stopServer() throws. ✓

The design is sound: lazy inline LoggerFactory.getLogger() (rather than a static field) is the correct choice — a static field initializer would trigger class-load and NoClassDefFoundError in the forked JVM where slf4j-api is absent from the classpath.

This review was generated by an AI agent, Hermès on behalf of @gnodet.

Use structured logging in IPC server

7bd8a48

Signed-off-by: Efe Gökdemir <efe@rexcode.co.uk>

gnodet-bot suggested changes Sep 23, 2026

View reviewed changes

Preserve diagnostics in forked IPC server

278d3be

Signed-off-by: Efe Gökdemir <efe@rexcode.co.uk>

gnodet-bot suggested changes Sep 23, 2026

View reviewed changes

Preserve forked IPC diagnostics

6f05a28

gnodet-bot reviewed Sep 23, 2026

View reviewed changes

test: bound forked IPC diagnostics test

d70ce42

gnodet-bot reviewed Sep 23, 2026

View reviewed changes

fix: clean up IPC server shutdown state

4e7382c

gnodet-bot reviewed Sep 23, 2026

View reviewed changes

test: always close forked IPC client

f6e89e1

gnodet-bot approved these changes Sep 23, 2026

View reviewed changes

cstamas added the bug Something isn't working label Sep 26, 2026

cstamas added this to the 2.0.24 milestone Sep 26, 2026

cstamas approved these changes Sep 26, 2026

View reviewed changes

cstamas merged commit 26b4de3 into apache:master Sep 26, 2026
20 checks passed

github-actions Bot assigned cstamas Sep 26, 2026

	LoggerFactory.getLogger(IpcServer.class).info(msg, args);
	LoggerFactory.getLogger(IpcServer.class).info(msg.replaceAll("%[sd]", "{}"), args);

	private static volatile boolean forkedProcess;
	static volatile boolean forkedProcess;

Conversation

efegokdemir commented Sep 23, 2026

Summary

Changes

Testing

Notes

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

efegokdemir commented Sep 23, 2026

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

efegokdemir commented Sep 23, 2026

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

gnodet-bot Sep 23, 2026

Choose a reason for hiding this comment

Uh oh!

gnodet-bot left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants