Skip to content

Commit ddfaecf

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 3108e8c commit ddfaecf

3 files changed

Lines changed: 117 additions & 3 deletions

File tree

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

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -318,8 +318,12 @@ private void verifyProtocolVersion(Connection connection) throws Exception {
318318
if (this.options.getOnGitHubTelemetry() != null) {
319319
connectParams.put("enableGitHubTelemetryForwarding", true);
320320
}
321-
var connectResponse = connection.rpc.invoke("connect", connectParams, ConnectResult.class).get(30,
322-
TimeUnit.SECONDS);
321+
// A legacy server rejects 'connect' and we fall back to 'ping' below, so
322+
// only that rejection is expected; anything else stays a warning.
323+
var connectResponse = connection.rpc
324+
.invoke("connect", connectParams, ConnectResult.class,
325+
cause -> cause instanceof JsonRpcException rpcEx && isUnsupportedConnectMethod(rpcEx))
326+
.get(30, TimeUnit.SECONDS);
323327
serverVersion = connectResponse.protocolVersion() != null
324328
? connectResponse.protocolVersion().intValue()
325329
: null;

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

Lines changed: 27 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import java.util.concurrent.Executors;
1919
import java.util.concurrent.atomic.AtomicLong;
2020
import java.util.function.BiConsumer;
21+
import java.util.function.Predicate;
2122
import java.util.logging.Level;
2223
import java.util.logging.Logger;
2324

@@ -105,6 +106,22 @@ public void registerMethodHandler(String method, BiConsumer<String, JsonNode> ha
105106
* Sends a JSON-RPC request and waits for the response.
106107
*/
107108
public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> responseType) {
109+
return invoke(method, params, responseType, ex -> false);
110+
}
111+
112+
/**
113+
* Sends a JSON-RPC request and waits for the response, logging the failure at
114+
* {@link Level#FINE} when {@code expectedFailure} accepts it.
115+
*
116+
* <p>
117+
* Callers that recover from one specific failure (for example probing for a
118+
* method that older servers do not implement) use this so the recovered failure
119+
* is not surfaced to users as a warning with a stack trace. The predicate
120+
* receives the unwrapped cause; every failure it rejects is still logged at
121+
* {@link Level#WARNING}.
122+
*/
123+
<T> CompletableFuture<T> invoke(String method, Object params, Class<T> responseType,
124+
Predicate<Throwable> expectedFailure) {
108125
long timingNanos = System.nanoTime();
109126
long id = requestIdCounter.incrementAndGet();
110127
var future = new CompletableFuture<JsonNode>();
@@ -138,14 +155,23 @@ public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> re
138155
throw new CompletionException(e);
139156
}
140157
}).exceptionally(ex -> {
141-
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
158+
Level failureLevel = expectedFailure.test(unwrapCompletion(ex)) ? Level.FINE : Level.WARNING;
159+
LoggingHelpers.logTiming(LOG, failureLevel, ex,
142160
"JsonRpc.invoke JSON-RPC request finished. Elapsed={Elapsed}, Method=" + method + ", RequestId="
143161
+ id + ", Status=Failed",
144162
timingNanos);
145163
throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
146164
});
147165
}
148166

167+
private static Throwable unwrapCompletion(Throwable ex) {
168+
Throwable cause = ex;
169+
while (cause instanceof CompletionException && cause.getCause() != null) {
170+
cause = cause.getCause();
171+
}
172+
return cause;
173+
}
174+
149175
/**
150176
* Sends a JSON-RPC notification (no response expected).
151177
*/

java/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

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

0 commit comments

Comments
 (0)