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..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 @@ -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) { @@ -1019,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) { 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 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);