From 134f55d1207055513788adcd03518603ef549a18 Mon Sep 17 00:00:00 2001 From: Zhangyi Yuan Date: Tue, 11 Aug 2026 10:17:57 +0800 Subject: [PATCH] fix(java): stop logging the legacy 'connect' probe failure as a warning CopilotClient probes the 'connect' RPC and falls back to 'ping' when the server does not implement it. JsonRpcClient.invoke logged every failed request at WARNING with a stack trace, so this fully recovered probe printed a scary 'Unhandled method connect' trace on every startup under the JUL default console handler. Give invoke an internal overload that takes the level used for failures and have the protocol-negotiation probe pass FINE. Unexpected failures still log at WARNING. Fixes #2291. --- .../com/github/copilot/CopilotClient.java | 8 +- .../com/github/copilot/JsonRpcClient.java | 28 ++++++- .../com/github/copilot/JsonRpcClientTest.java | 84 +++++++++++++++++++ 3 files changed, 117 insertions(+), 3 deletions(-) diff --git a/java/sdk/src/main/java/com/github/copilot/CopilotClient.java b/java/sdk/src/main/java/com/github/copilot/CopilotClient.java index cdd1b9ff3..30a1819e2 100644 --- a/java/sdk/src/main/java/com/github/copilot/CopilotClient.java +++ b/java/sdk/src/main/java/com/github/copilot/CopilotClient.java @@ -647,8 +647,12 @@ private void verifyProtocolVersion(Connection connection) throws Exception { if (this.options.getOnGitHubTelemetry() != null) { connectParams.put("enableGitHubTelemetryForwarding", true); } - var connectResponse = connection.rpc.invoke("connect", connectParams, ConnectResult.class).get(30, - TimeUnit.SECONDS); + // A legacy server rejects 'connect' and we fall back to 'ping' below, so + // only that rejection is expected; anything else stays a warning. + var connectResponse = connection.rpc + .invoke("connect", connectParams, ConnectResult.class, + cause -> cause instanceof JsonRpcException rpcEx && isUnsupportedConnectMethod(rpcEx)) + .get(30, TimeUnit.SECONDS); serverVersion = connectResponse.protocolVersion() != null ? connectResponse.protocolVersion().intValue() : null; diff --git a/java/sdk/src/main/java/com/github/copilot/JsonRpcClient.java b/java/sdk/src/main/java/com/github/copilot/JsonRpcClient.java index 550bd4ca4..59d6d4556 100644 --- a/java/sdk/src/main/java/com/github/copilot/JsonRpcClient.java +++ b/java/sdk/src/main/java/com/github/copilot/JsonRpcClient.java @@ -19,6 +19,7 @@ import java.util.concurrent.atomic.AtomicLong; import java.util.function.BiConsumer; import java.util.function.Consumer; +import java.util.function.Predicate; import java.util.logging.Level; import java.util.logging.Logger; @@ -134,6 +135,22 @@ public void registerMethodHandler(String method, BiConsumer ha * Sends a JSON-RPC request and waits for the response. */ public CompletableFuture invoke(String method, Object params, Class responseType) { + return invoke(method, params, responseType, ex -> false); + } + + /** + * Sends a JSON-RPC request and waits for the response, logging the failure at + * {@link Level#FINE} when {@code expectedFailure} accepts it. + * + *

+ * Callers that recover from one specific failure (for example probing for a + * method that older servers do not implement) use this so the recovered failure + * is not surfaced to users as a warning with a stack trace. The predicate + * receives the unwrapped cause; every failure it rejects is still logged at + * {@link Level#WARNING}. + */ + CompletableFuture invoke(String method, Object params, Class responseType, + Predicate expectedFailure) { long timingNanos = System.nanoTime(); long id = requestIdCounter.incrementAndGet(); var future = new CompletableFuture(); @@ -167,7 +184,8 @@ public CompletableFuture invoke(String method, Object params, Class re throw new CompletionException(e); } }).exceptionally(ex -> { - LoggingHelpers.logTiming(LOG, Level.WARNING, ex, + Level failureLevel = expectedFailure.test(unwrapCompletion(ex)) ? Level.FINE : Level.WARNING; + LoggingHelpers.logTiming(LOG, failureLevel, ex, "JsonRpc.invoke JSON-RPC request finished. Elapsed={Elapsed}, Method=" + method + ", RequestId=" + id + ", Status=Failed", timingNanos); @@ -175,6 +193,14 @@ public CompletableFuture invoke(String method, Object params, Class re }); } + private static Throwable unwrapCompletion(Throwable ex) { + Throwable cause = ex; + while (cause instanceof CompletionException && cause.getCause() != null) { + cause = cause.getCause(); + } + return cause; + } + /** * Sends a JSON-RPC notification (no response expected). */ diff --git a/java/sdk/src/test/java/com/github/copilot/JsonRpcClientTest.java b/java/sdk/src/test/java/com/github/copilot/JsonRpcClientTest.java index d6c0b5e14..999de065f 100644 --- a/java/sdk/src/test/java/com/github/copilot/JsonRpcClientTest.java +++ b/java/sdk/src/test/java/com/github/copilot/JsonRpcClientTest.java @@ -12,11 +12,18 @@ import java.net.ServerSocket; import java.net.Socket; import java.nio.charset.StandardCharsets; +import java.util.List; import java.util.Map; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.ExecutionException; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReference; +import java.util.function.Function; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; import org.junit.jupiter.api.Test; @@ -456,4 +463,81 @@ void testCloseWithPendingRequests() throws Exception { pair.serverSide.close(); pair.serverSocket.close(); } + + // ---- invoke() failure log level ---- + + private static final class RecordingLogHandler extends Handler { + + private final List records = new CopyOnWriteArrayList<>(); + + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() { + } + + @Override + public void close() { + } + } + + /** + * Runs an invocation that the server rejects with {@code errorCode} and returns + * everything the {@link JsonRpcClient} logger emitted while it ran. + */ + private List captureLogsForFailedInvoke(Function> invoker, + int errorCode) throws Exception { + var logger = Logger.getLogger(JsonRpcClient.class.getName()); + var handler = new RecordingLogHandler(); + logger.addHandler(handler); + try (var pair = createSocketPair()) { + CompletableFuture future = invoker.apply(pair.client); + + String request = readRpcMessage(pair.serverSide.getInputStream()); + long id = MAPPER.readTree(request).get("id").asLong(); + writeRpcMessage(pair.serverSide.getOutputStream(), "{\"jsonrpc\":\"2.0\",\"id\":" + id + ",\"error\":{" + + "\"code\":" + errorCode + ",\"message\":\"Unhandled method connect\"}}"); + + assertThrows(ExecutionException.class, () -> future.get(5, TimeUnit.SECONDS)); + return handler.records; + } finally { + logger.removeHandler(handler); + } + } + + /** Matches the JSON-RPC "method not found" rejection from a legacy server. */ + private static boolean isMethodNotFound(Throwable cause) { + return cause instanceof JsonRpcException rpcEx && rpcEx.getCode() == -32601; + } + + @Test + void testInvokeLogsFailureAtWarningByDefault() throws Exception { + var records = captureLogsForFailedInvoke(client -> client.invoke("connect", Map.of(), JsonNode.class), -32601); + + assertTrue(records.stream().anyMatch(r -> r.getLevel() == Level.WARNING), + "Callers that declare no expected failure should still get a WARNING"); + } + + @Test + void testInvokeDowngradesExpectedFailure() throws Exception { + var records = captureLogsForFailedInvoke( + client -> client.invoke("connect", Map.of(), JsonNode.class, JsonRpcClientTest::isMethodNotFound), + -32601); + + assertTrue(records.stream().noneMatch(r -> r.getLevel().intValue() >= Level.WARNING.intValue()), + "A failure the caller expects and recovers from must not be logged at WARNING"); + } + + @Test + void testInvokeKeepsWarningForUnexpectedFailure() throws Exception { + var records = captureLogsForFailedInvoke( + client -> client.invoke("connect", Map.of(), JsonNode.class, JsonRpcClientTest::isMethodNotFound), + -32603); + + assertTrue(records.stream().anyMatch(r -> r.getLevel() == Level.WARNING), + "A failure the predicate rejects must still be logged at WARNING"); + } }