From 70d172143e8e1b3eed4a010fb9ecb7cc2151f4f1 Mon Sep 17 00:00:00 2001 From: Jerome Louvel <374450+jlouvel@users.noreply.github.com> Date: Fri, 30 Oct 2026 10:36:56 -0400 Subject: [PATCH 1/3] Log the HTTP client steps at FINE and keep the FINE logs of CI test runs To diagnose the intermittent Communication Error (1001) of SecurityTestCase, the Netty client logs at FINE each connection opened, reused, discarded or closed, each request sent, each response head and end received, and each exchange failure. The new "ci-logging" profile writes the FINE logs of the core tests to target/restlet-fine.log, which CI uploads when the build fails. Refs #1601 Co-Authored-By: Claude Opus 5.5 --- .github/workflows/build.yaml | 14 +++++++++++-- changes.md | 3 +++ org.restlet/pom.xml | 21 +++++++++++++++++++ .../restlet/engine/netty/NettyClientCall.java | 5 +++++ .../engine/netty/NettyClientHelper.java | 14 ++++++++++++- org.restlet/src/test/ci-logging.properties | 16 ++++++++++++++ 6 files changed, 70 insertions(+), 3 deletions(-) create mode 100644 org.restlet/src/test/ci-logging.properties diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index 9336ab62e5..dfb121aeb9 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -27,8 +27,9 @@ jobs: java-version: ${{ env.JAVA_VERSION }} cache: 'maven' - name: Build and test with Maven - # verify also runs the Spotless check, the JaCoCo coverage check and SpotBugs - run: ./mvnw -B verify -P default,test + # verify also runs the Spotless check, the JaCoCo coverage check and SpotBugs. The + # ci-logging profile writes the FINE logs of the core tests to a file (issue #1601). + run: ./mvnw -B verify -P default,test,ci-logging - name: Check Javadoc run: ./mvnw -B -q compile javadoc:javadoc - name: Upload coverage and static analysis reports @@ -40,3 +41,12 @@ jobs: **/target/site/jacoco/ **/target/spotbugsXml.xml if-no-files-found: ignore + - name: Upload test logs + if: failure() + uses: actions/upload-artifact@v7 + with: + name: test-logs + path: | + **/target/restlet-fine.log + **/target/surefire-reports/ + if-no-files-found: ignore diff --git a/changes.md b/changes.md index 3f7022419d..cd559427ed 100644 --- a/changes.md +++ b/changes.md @@ -191,6 +191,9 @@ Changes log - Added Netty 4.2.19 (imported with the `netty-bom`). CI builds with Java 25. - The `dangling-doc-comments` lint, new in Java 23, is disabled because license headers use Javadoc-style comments. + - The HTTP client logs the steps of its exchanges and connections at the FINE level. CI + writes the FINE logs of the core tests to `target/restlet-fine.log` ("ci-logging" + profile) and uploads them when the build fails. Issue #1601. - 3.0 Milestone 1 (10-11-2026) - Breaking changes diff --git a/org.restlet/pom.xml b/org.restlet/pom.xml index 5f2ad34ae7..348ff92708 100644 --- a/org.restlet/pom.xml +++ b/org.restlet/pom.xml @@ -199,6 +199,27 @@ + + + ci-logging + + + + maven-surefire-plugin + + + default-test + + + ${project.basedir}/src/test/ci-logging.properties + + + + + + + + quic-linux-x86_64 diff --git a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java index 8b98638774..fea891c1c0 100644 --- a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java +++ b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java @@ -784,6 +784,7 @@ private void writeRequest(Representation entity) throws IOException { lastContent = withTrailers; } check(ch.writeAndFlush(lastContent)); + helper.getLogger().fine(() -> "Sent the request " + method + " " + target + " on " + ch); lock.lock(); try { @@ -907,6 +908,8 @@ private void awaitHead() throws IOException { * @param response The response head. */ void onResponseHead(HttpResponse response) { + helper.getLogger() + .fine(() -> "Received the response head " + response.status() + " on " + channel); for (Map.Entry entry : response.headers()) { String name = kind.isStream() ? entry.getKey().toLowerCase(Locale.ROOT) : entry.getKey(); @@ -961,6 +964,7 @@ boolean onResponseContent(ByteBuf content) { /** Called on the event loop when the response is fully received. */ void onResponseComplete(io.netty.handler.codec.http.HttpHeaders trailers) { + helper.getLogger().fine(() -> "Received the end of the response on " + channel); org.restlet.Response currentResponse = response; if (currentResponse != null) { for (Map.Entry trailer : trailers) { @@ -996,6 +1000,7 @@ void onResponseComplete(io.netty.handler.codec.http.HttpHeaders trailers) { * @param cause The failure cause. */ void onFailure(Throwable cause) { + helper.logFailure("The exchange failed on " + channel, cause); boolean notifyResponseFailure = false; boolean responseHeadReceived; lock.lock(); diff --git a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientHelper.java b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientHelper.java index b72c58fc19..4fad595e2b 100644 --- a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientHelper.java +++ b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientHelper.java @@ -500,9 +500,13 @@ && getProxyHost() == null) { Channel channel; while ((channel = pool.idle.pollFirst()) != null) { if (channel.isActive()) { + Channel reused = channel; + getLogger().fine(() -> "Reusing the idle connection " + reused); bindHttp1(channel, call); return channel; } + Channel inactive = channel; + getLogger().fine(() -> "Discarding the inactive idle connection " + inactive); } if (getTransportMode() == TransportMode.HTTP1_1) { @@ -609,8 +613,10 @@ void release(Channel channel, boolean reusable) { OriginPool pool = channel.attr(POOL).get(); if (reusable && channel.isActive() && pool != null && group != null) { + getLogger().fine(() -> "Returning the connection " + channel + " to the pool"); pool.idle.offerFirst(channel); } else { + getLogger().fine(() -> "Closing the connection " + channel + ", reusable=" + reusable); channel.close(); } } @@ -714,7 +720,12 @@ protected void initChannel(SocketChannel ch) { timeout, "Unable to connect to " + pool.host + ":" + pool.port); connections.add(channel); - channel.closeFuture().addListener(f -> releaseConnection(pool, true)); + channel.closeFuture() + .addListener( + f -> { + releaseConnection(pool, true); + getLogger().fine(() -> "Closed the connection " + channel); + }); acquired = false; Promise ready = channel.attr(READY).get(); @@ -724,6 +735,7 @@ protected void initChannel(SocketChannel ch) { channel.close(); throw e; } + getLogger().fine(() -> "Opened the connection " + channel); return channel; } finally { if (acquired) { diff --git a/org.restlet/src/test/ci-logging.properties b/org.restlet/src/test/ci-logging.properties new file mode 100644 index 0000000000..9a54abbbd9 --- /dev/null +++ b/org.restlet/src/test/ci-logging.properties @@ -0,0 +1,16 @@ +# Logging of the tests in CI (profile "ci-logging"): the console keeps the INFO level, while the +# FINE level of the Restlet loggers, including the steps of the Netty client connector, goes to +# target/restlet-fine.log, uploaded when the build fails. Diagnoses intermittent failures such as +# the connector errors of SecurityTestCase (issue #1601). +handlers=java.util.logging.ConsoleHandler,java.util.logging.FileHandler +.level=INFO +org.restlet.level=FINE + +java.util.logging.ConsoleHandler.level=INFO + +java.util.logging.FileHandler.level=FINE +java.util.logging.FileHandler.pattern=target/restlet-fine.log +java.util.logging.FileHandler.limit=0 +java.util.logging.FileHandler.append=true +java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter +java.util.logging.SimpleFormatter.format=%1$tT.%1$tL [%3$s] %4$s %5$s%6$s%n From a5a64cf77755daba23a662a4cd0942cfe1568f45 Mon Sep 17 00:00:00 2001 From: Jerome Louvel <374450+jlouvel@users.noreply.github.com> Date: Sat, 31 Oct 2026 02:05:17 -0400 Subject: [PATCH 2/3] fix: log Netty client exchange failures only when they are not ignored Co-Authored-By: Claude Opus 5.5 --- .../src/main/java/org/restlet/engine/netty/NettyClientCall.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java index fea891c1c0..3b976b5c9d 100644 --- a/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java +++ b/org.restlet/src/main/java/org/restlet/engine/netty/NettyClientCall.java @@ -1000,7 +1000,6 @@ void onResponseComplete(io.netty.handler.codec.http.HttpHeaders trailers) { * @param cause The failure cause. */ void onFailure(Throwable cause) { - helper.logFailure("The exchange failed on " + channel, cause); boolean notifyResponseFailure = false; boolean responseHeadReceived; lock.lock(); @@ -1024,6 +1023,7 @@ void onFailure(Throwable cause) { } finally { lock.unlock(); } + helper.logFailure("The exchange failed on " + channel, cause); ChannelInputStream stream = this.body; org.restlet.Request request = currentRequest; if (request != null) { From 0f66c6d1905af951679a5b91cb1a27a36bf3d315 Mon Sep 17 00:00:00 2001 From: Jerome Louvel <374450+jlouvel@users.noreply.github.com> Date: Sun, 1 Nov 2026 09:13:45 -0500 Subject: [PATCH 3/3] test: give Http1LookaheadTestCase's client call a helper for its FINE logs The client call now logs the end of the response through its helper. Co-Authored-By: Claude Opus 5.5 --- .../org/restlet/engine/netty/Http1LookaheadTestCase.java | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/org.restlet/src/test/java/org/restlet/engine/netty/Http1LookaheadTestCase.java b/org.restlet/src/test/java/org/restlet/engine/netty/Http1LookaheadTestCase.java index 84d3153a44..8ee50b6534 100644 --- a/org.restlet/src/test/java/org/restlet/engine/netty/Http1LookaheadTestCase.java +++ b/org.restlet/src/test/java/org/restlet/engine/netty/Http1LookaheadTestCase.java @@ -47,6 +47,7 @@ import org.restlet.data.MediaType; import org.restlet.data.Protocol; import org.restlet.data.Reference; +import org.restlet.engine.connector.HttpClientHelper; import org.restlet.engine.connector.HttpServerHelper; class Http1LookaheadTestCase { @@ -288,10 +289,12 @@ public boolean awaitTermination(long timeout, TimeUnit unit) { @Test void publishesClientCompletionBeforeReleasingAnEmptyBodyConsumer() throws Exception { + var helper = new HttpClientHelper(null); var trailers = new io.netty.handler.codec.http.DefaultHttpHeaders(); - new NettyClientCall(null, "GET", new Reference("http://localhost/"), "/", false) + new NettyClientCall(helper, "GET", new Reference("http://localhost/"), "/", false) .onResponseComplete(trailers); - var call = new NettyClientCall(null, "GET", new Reference("http://localhost/"), "/", false); + var call = + new NettyClientCall(helper, "GET", new Reference("http://localhost/"), "/", false); var body = new ChannelInputStream(null, 0); var bodyField = NettyClientCall.class.getDeclaredField("body"); bodyField.setAccessible(true);