Skip to content

Commit 134f55d

Browse files
author
Zhangyi Yuan
committed
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.
1 parent 1935fd3 commit 134f55d

3 files changed

Lines changed: 117 additions & 3 deletions

File tree

java/sdk/src/main/java/com/github/copilot/CopilotClient.java

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -647,8 +647,12 @@ private void verifyProtocolVersion(Connection connection) throws Exception {
647647
if (this.options.getOnGitHubTelemetry() != null) {
648648
connectParams.put("enableGitHubTelemetryForwarding", true);
649649
}
650-
var connectResponse = connection.rpc.invoke("connect", connectParams, ConnectResult.class).get(30,
651-
TimeUnit.SECONDS);
650+
// A legacy server rejects 'connect' and we fall back to 'ping' below, so
651+
// only that rejection is expected; anything else stays a warning.
652+
var connectResponse = connection.rpc
653+
.invoke("connect", connectParams, ConnectResult.class,
654+
cause -> cause instanceof JsonRpcException rpcEx && isUnsupportedConnectMethod(rpcEx))
655+
.get(30, TimeUnit.SECONDS);
652656
serverVersion = connectResponse.protocolVersion() != null
653657
? connectResponse.protocolVersion().intValue()
654658
: null;

java/sdk/src/main/java/com/github/copilot/JsonRpcClient.java

Lines changed: 27 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import java.util.concurrent.atomic.AtomicLong;
2020
import java.util.function.BiConsumer;
2121
import java.util.function.Consumer;
22+
import java.util.function.Predicate;
2223
import java.util.logging.Level;
2324
import java.util.logging.Logger;
2425

@@ -134,6 +135,22 @@ public void registerMethodHandler(String method, BiConsumer<String, JsonNode> ha
134135
* Sends a JSON-RPC request and waits for the response.
135136
*/
136137
public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> responseType) {
138+
return invoke(method, params, responseType, ex -> false);
139+
}
140+
141+
/**
142+
* Sends a JSON-RPC request and waits for the response, logging the failure at
143+
* {@link Level#FINE} when {@code expectedFailure} accepts it.
144+
*
145+
* <p>
146+
* Callers that recover from one specific failure (for example probing for a
147+
* method that older servers do not implement) use this so the recovered failure
148+
* is not surfaced to users as a warning with a stack trace. The predicate
149+
* receives the unwrapped cause; every failure it rejects is still logged at
150+
* {@link Level#WARNING}.
151+
*/
152+
<T> CompletableFuture<T> invoke(String method, Object params, Class<T> responseType,
153+
Predicate<Throwable> expectedFailure) {
137154
long timingNanos = System.nanoTime();
138155
long id = requestIdCounter.incrementAndGet();
139156
var future = new CompletableFuture<JsonNode>();
@@ -167,14 +184,23 @@ public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> re
167184
throw new CompletionException(e);
168185
}
169186
}).exceptionally(ex -> {
170-
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
187+
Level failureLevel = expectedFailure.test(unwrapCompletion(ex)) ? Level.FINE : Level.WARNING;
188+
LoggingHelpers.logTiming(LOG, failureLevel, ex,
171189
"JsonRpc.invoke JSON-RPC request finished. Elapsed={Elapsed}, Method=" + method + ", RequestId="
172190
+ id + ", Status=Failed",
173191
timingNanos);
174192
throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
175193
});
176194
}
177195

196+
private static Throwable unwrapCompletion(Throwable ex) {
197+
Throwable cause = ex;
198+
while (cause instanceof CompletionException && cause.getCause() != null) {
199+
cause = cause.getCause();
200+
}
201+
return cause;
202+
}
203+
178204
/**
179205
* Sends a JSON-RPC notification (no response expected).
180206
*/

java/sdk/src/test/java/com/github/copilot/JsonRpcClientTest.java

Lines changed: 84 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,11 +12,18 @@
1212
import java.net.ServerSocket;
1313
import java.net.Socket;
1414
import java.nio.charset.StandardCharsets;
15+
import java.util.List;
1516
import java.util.Map;
1617
import java.util.concurrent.CompletableFuture;
18+
import java.util.concurrent.CopyOnWriteArrayList;
1719
import java.util.concurrent.ExecutionException;
1820
import java.util.concurrent.TimeUnit;
1921
import java.util.concurrent.atomic.AtomicReference;
22+
import java.util.function.Function;
23+
import java.util.logging.Handler;
24+
import java.util.logging.Level;
25+
import java.util.logging.LogRecord;
26+
import java.util.logging.Logger;
2027

2128
import org.junit.jupiter.api.Test;
2229

@@ -456,4 +463,81 @@ void testCloseWithPendingRequests() throws Exception {
456463
pair.serverSide.close();
457464
pair.serverSocket.close();
458465
}
466+
467+
// ---- invoke() failure log level ----
468+
469+
private static final class RecordingLogHandler extends Handler {
470+
471+
private final List<LogRecord> records = new CopyOnWriteArrayList<>();
472+
473+
@Override
474+
public void publish(LogRecord record) {
475+
records.add(record);
476+
}
477+
478+
@Override
479+
public void flush() {
480+
}
481+
482+
@Override
483+
public void close() {
484+
}
485+
}
486+
487+
/**
488+
* Runs an invocation that the server rejects with {@code errorCode} and returns
489+
* everything the {@link JsonRpcClient} logger emitted while it ran.
490+
*/
491+
private List<LogRecord> captureLogsForFailedInvoke(Function<JsonRpcClient, CompletableFuture<?>> invoker,
492+
int errorCode) throws Exception {
493+
var logger = Logger.getLogger(JsonRpcClient.class.getName());
494+
var handler = new RecordingLogHandler();
495+
logger.addHandler(handler);
496+
try (var pair = createSocketPair()) {
497+
CompletableFuture<?> future = invoker.apply(pair.client);
498+
499+
String request = readRpcMessage(pair.serverSide.getInputStream());
500+
long id = MAPPER.readTree(request).get("id").asLong();
501+
writeRpcMessage(pair.serverSide.getOutputStream(), "{\"jsonrpc\":\"2.0\",\"id\":" + id + ",\"error\":{"
502+
+ "\"code\":" + errorCode + ",\"message\":\"Unhandled method connect\"}}");
503+
504+
assertThrows(ExecutionException.class, () -> future.get(5, TimeUnit.SECONDS));
505+
return handler.records;
506+
} finally {
507+
logger.removeHandler(handler);
508+
}
509+
}
510+
511+
/** Matches the JSON-RPC "method not found" rejection from a legacy server. */
512+
private static boolean isMethodNotFound(Throwable cause) {
513+
return cause instanceof JsonRpcException rpcEx && rpcEx.getCode() == -32601;
514+
}
515+
516+
@Test
517+
void testInvokeLogsFailureAtWarningByDefault() throws Exception {
518+
var records = captureLogsForFailedInvoke(client -> client.invoke("connect", Map.of(), JsonNode.class), -32601);
519+
520+
assertTrue(records.stream().anyMatch(r -> r.getLevel() == Level.WARNING),
521+
"Callers that declare no expected failure should still get a WARNING");
522+
}
523+
524+
@Test
525+
void testInvokeDowngradesExpectedFailure() throws Exception {
526+
var records = captureLogsForFailedInvoke(
527+
client -> client.invoke("connect", Map.of(), JsonNode.class, JsonRpcClientTest::isMethodNotFound),
528+
-32601);
529+
530+
assertTrue(records.stream().noneMatch(r -> r.getLevel().intValue() >= Level.WARNING.intValue()),
531+
"A failure the caller expects and recovers from must not be logged at WARNING");
532+
}
533+
534+
@Test
535+
void testInvokeKeepsWarningForUnexpectedFailure() throws Exception {
536+
var records = captureLogsForFailedInvoke(
537+
client -> client.invoke("connect", Map.of(), JsonNode.class, JsonRpcClientTest::isMethodNotFound),
538+
-32603);
539+
540+
assertTrue(records.stream().anyMatch(r -> r.getLevel() == Level.WARNING),
541+
"A failure the predicate rejects must still be logged at WARNING");
542+
}
459543
}

0 commit comments

Comments
 (0)