Skip to content

Commit 24b7a64

Browse files
Copilotedburns
Copilot
and
edburns
authored
Port enableSessionTelemetry option and SDK tracing diagnostics from reference implementation
Co-authored-by: edburns <75821+edburns@users.noreply.github.com>
1 parent b6dff3e commit 24b7a64

11 files changed

Lines changed: 361 additions & 1 deletion

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

Lines changed: 39 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -188,6 +188,7 @@ private CompletableFuture<Connection> startCore() {
188188

189189
private Connection startCoreBody() {
190190
Process process = null;
191+
long startNanos = System.nanoTime();
191192
try {
192193
JsonRpcClient rpc;
193194

@@ -202,6 +203,9 @@ private Connection startCoreBody() {
202203
processInfo.port());
203204
}
204205

206+
LoggingHelpers.logTiming(LOG, Level.FINE, "CopilotClient.start transport setup complete. Elapsed={Elapsed}",
207+
startNanos);
208+
205209
Connection connection = new Connection(rpc, process, new ServerRpc(rpc::invoke));
206210

207211
// Register handlers for server-to-client calls
@@ -211,10 +215,16 @@ private Connection startCoreBody() {
211215

212216
// Verify protocol version
213217
verifyProtocolVersion(connection);
218+
LoggingHelpers.logTiming(LOG, Level.FINE,
219+
"CopilotClient.start protocol verification complete. Elapsed={Elapsed}", startNanos);
214220

215-
LOG.info("Copilot client connected");
221+
LoggingHelpers.logTiming(LOG, Level.FINE, "CopilotClient.start complete. Elapsed={Elapsed}", startNanos);
216222
return connection;
217223
} catch (Exception e) {
224+
if (!(e instanceof java.util.concurrent.CancellationException)) {
225+
LoggingHelpers.logTiming(LOG, Level.WARNING, e, "CopilotClient.start failed. Elapsed={Elapsed}",
226+
startNanos);
227+
}
218228
// Clean up the spawned process if connection setup failed
219229
if (process != null) {
220230
cleanupCliProcess(process);
@@ -417,18 +427,23 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
417427
+ "new SessionConfig().setOnPermissionRequest(PermissionHandler.APPROVE_ALL)"));
418428
}
419429
return ensureConnected().thenCompose(connection -> {
430+
long totalNanos = System.nanoTime();
420431
// Pre-generate session ID so the session can be registered before the RPC call,
421432
// ensuring no events emitted by the CLI during creation are lost.
422433
String sessionId = config.getSessionId() != null
423434
? config.getSessionId()
424435
: java.util.UUID.randomUUID().toString();
425436

437+
long setupNanos = System.nanoTime();
426438
var session = new CopilotSession(sessionId, connection.rpc);
427439
if (options.getExecutor() != null) {
428440
session.setExecutor(options.getExecutor());
429441
}
430442
SessionRequestBuilder.configureSession(session, config);
431443
sessions.put(sessionId, session);
444+
LoggingHelpers.logTiming(LOG, Level.FINE,
445+
"CopilotClient.createSession local setup complete. Elapsed={Elapsed}, SessionId=" + sessionId,
446+
setupNanos);
432447

433448
// Extract transform callbacks from the system message config.
434449
// Callbacks are registered with the session; a wire-safe copy of the
@@ -444,7 +459,12 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
444459
request.setSystemMessage(extracted.wireSystemMessage());
445460
}
446461

462+
long rpcNanos = System.nanoTime();
447463
return connection.rpc.invoke("session.create", request, CreateSessionResponse.class).thenApply(response -> {
464+
LoggingHelpers.logTiming(LOG, Level.FINE,
465+
"CopilotClient.createSession session creation request completed. Elapsed={Elapsed}, SessionId="
466+
+ sessionId,
467+
rpcNanos);
448468
session.setWorkspacePath(response.workspacePath());
449469
session.setCapabilities(response.capabilities());
450470
// If the server returned a different sessionId (e.g. a v2 CLI that ignores
@@ -455,9 +475,13 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
455475
session.setActiveSessionId(returnedId);
456476
sessions.put(returnedId, session);
457477
}
478+
LoggingHelpers.logTiming(LOG, Level.FINE,
479+
"CopilotClient.createSession complete. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
458480
return session;
459481
}).exceptionally(ex -> {
460482
sessions.remove(sessionId);
483+
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
484+
"CopilotClient.createSession failed. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
461485
throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
462486
});
463487
});
@@ -496,13 +520,18 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
496520
+ "new ResumeSessionConfig().setOnPermissionRequest(PermissionHandler.APPROVE_ALL)"));
497521
}
498522
return ensureConnected().thenCompose(connection -> {
523+
long totalNanos = System.nanoTime();
499524
// Register the session before the RPC call to avoid missing early events.
525+
long setupNanos = System.nanoTime();
500526
var session = new CopilotSession(sessionId, connection.rpc);
501527
if (options.getExecutor() != null) {
502528
session.setExecutor(options.getExecutor());
503529
}
504530
SessionRequestBuilder.configureSession(session, config);
505531
sessions.put(sessionId, session);
532+
LoggingHelpers.logTiming(LOG, Level.FINE,
533+
"CopilotClient.resumeSession local setup complete. Elapsed={Elapsed}, SessionId=" + sessionId,
534+
setupNanos);
506535

507536
// Extract transform callbacks from the system message config.
508537
var extracted = SessionRequestBuilder.extractTransformCallbacks(config.getSystemMessage());
@@ -515,7 +544,12 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
515544
request.setSystemMessage(extracted.wireSystemMessage());
516545
}
517546

547+
long rpcNanos = System.nanoTime();
518548
return connection.rpc.invoke("session.resume", request, ResumeSessionResponse.class).thenApply(response -> {
549+
LoggingHelpers.logTiming(LOG, Level.FINE,
550+
"CopilotClient.resumeSession session resume request completed. Elapsed={Elapsed}, SessionId="
551+
+ sessionId,
552+
rpcNanos);
519553
session.setWorkspacePath(response.workspacePath());
520554
session.setCapabilities(response.capabilities());
521555
// If the server returned a different sessionId than what was requested, re-key.
@@ -525,9 +559,13 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
525559
session.setActiveSessionId(returnedId);
526560
sessions.put(returnedId, session);
527561
}
562+
LoggingHelpers.logTiming(LOG, Level.FINE,
563+
"CopilotClient.resumeSession complete. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
528564
return session;
529565
}).exceptionally(ex -> {
530566
sessions.remove(sessionId);
567+
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
568+
"CopilotClient.resumeSession failed. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
531569
throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
532570
});
533571
});

‎src/main/java/com/github/copilot/sdk/CopilotSession.java‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -497,13 +497,24 @@ public CompletableFuture<String> send(MessageOptions options) {
497497
*/
498498
public CompletableFuture<AssistantMessageEvent> sendAndWait(MessageOptions options, long timeoutMs) {
499499
ensureNotTerminated();
500+
long totalNanos = System.nanoTime();
500501
var future = new CompletableFuture<AssistantMessageEvent>();
501502
var lastAssistantMessage = new AtomicReference<AssistantMessageEvent>();
503+
var firstAssistantMessageLogged = new java.util.concurrent.atomic.AtomicBoolean(false);
502504

503505
Consumer<SessionEvent> handler = evt -> {
504506
if (evt instanceof AssistantMessageEvent msg) {
505507
lastAssistantMessage.set(msg);
508+
if (firstAssistantMessageLogged.compareAndSet(false, true)) {
509+
LoggingHelpers.logTiming(LOG, Level.FINE,
510+
"CopilotSession.sendAndWait first assistant message. Elapsed={Elapsed}, SessionId="
511+
+ sessionId,
512+
totalNanos);
513+
}
506514
} else if (evt instanceof SessionIdleEvent) {
515+
LoggingHelpers.logTiming(LOG, Level.FINE,
516+
"CopilotSession.sendAndWait idle received. Elapsed={Elapsed}, SessionId=" + sessionId,
517+
totalNanos);
507518
future.complete(lastAssistantMessage.get());
508519
} else if (evt instanceof SessionErrorEvent errorEvent) {
509520
String message = errorEvent.getData() != null ? errorEvent.getData().message() : "session error";
@@ -568,8 +579,23 @@ public CompletableFuture<AssistantMessageEvent> sendAndWait(MessageOptions optio
568579
}
569580
if (!result.isDone()) {
570581
if (ex != null) {
582+
if (ex instanceof TimeoutException) {
583+
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
584+
"CopilotSession.sendAndWait failed. Elapsed={Elapsed}, SessionId=" + sessionId
585+
+ ", CompletedBy=timeout",
586+
totalNanos);
587+
} else if (!(ex instanceof java.util.concurrent.CancellationException)) {
588+
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
589+
"CopilotSession.sendAndWait failed. Elapsed={Elapsed}, SessionId=" + sessionId
590+
+ ", CompletedBy=error",
591+
totalNanos);
592+
}
571593
result.completeExceptionally(ex);
572594
} else {
595+
LoggingHelpers.logTiming(
596+
LOG, Level.FINE, "CopilotSession.sendAndWait complete. Elapsed={Elapsed}, SessionId="
597+
+ sessionId + ", CompletedBy=idle, AssistantMessageReceived=" + (r != null),
598+
totalNanos);
573599
result.complete(r);
574600
}
575601
}

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

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,7 @@ public void registerMethodHandler(String method, BiConsumer<String, JsonNode> ha
104104
* Sends a JSON-RPC request and waits for the response.
105105
*/
106106
public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> responseType) {
107+
long timingNanos = System.nanoTime();
107108
long id = requestIdCounter.incrementAndGet();
108109
var future = new CompletableFuture<JsonNode>();
109110
pendingRequests.put(id, future);
@@ -123,13 +124,23 @@ public <T> CompletableFuture<T> invoke(String method, Object params, Class<T> re
123124

124125
return future.thenApply(result -> {
125126
try {
127+
LoggingHelpers.logTiming(LOG, Level.FINE,
128+
"JsonRpc.invoke JSON-RPC request finished. Elapsed={Elapsed}, Method=" + method + ", RequestId="
129+
+ id + ", Status=Succeeded",
130+
timingNanos);
126131
if (responseType == Void.class || responseType == void.class) {
127132
return null;
128133
}
129134
return MAPPER.treeToValue(result, responseType);
130135
} catch (JsonProcessingException e) {
131136
throw new CompletionException(e);
132137
}
138+
}).exceptionally(ex -> {
139+
LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
140+
"JsonRpc.invoke JSON-RPC request finished. Elapsed={Elapsed}, Method=" + method + ", RequestId="
141+
+ id + ", Status=Failed",
142+
timingNanos);
143+
throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
133144
});
134145
}
135146

‎src/main/java/com/github/copilot/sdk/LoggingHelpers.java‎

Lines changed: 77 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,77 @@
1+
/*---------------------------------------------------------------------------------------------
2+
* Copyright (c) Microsoft Corporation. All rights reserved.
3+
*--------------------------------------------------------------------------------------------*/
4+
5+
package com.github.copilot.sdk;
6+
7+
import java.util.concurrent.TimeUnit;
8+
import java.util.logging.Level;
9+
import java.util.logging.Logger;
10+
11+
/**
12+
* Internal helper for timing-based diagnostic logging.
13+
*/
14+
final class LoggingHelpers {
15+
16+
private LoggingHelpers() {
17+
// Utility class
18+
}
19+
20+
/**
21+
* Formats elapsed time as a human-readable duration string.
22+
*
23+
* @param startNanos
24+
* the start time from {@link System#nanoTime()}
25+
* @return formatted duration (e.g. "PT0.123S")
26+
*/
27+
static String formatElapsed(long startNanos) {
28+
long elapsedNanos = System.nanoTime() - startNanos;
29+
long millis = TimeUnit.NANOSECONDS.toMillis(elapsedNanos);
30+
return String.format("PT%d.%03dS", millis / 1000, millis % 1000);
31+
}
32+
33+
/**
34+
* Logs a timing message at the given level if the logger accepts it.
35+
*
36+
* @param logger
37+
* the logger to use
38+
* @param level
39+
* the log level
40+
* @param message
41+
* the message template
42+
* @param startNanos
43+
* the start time from {@link System#nanoTime()}
44+
*/
45+
static void logTiming(Logger logger, Level level, String message, long startNanos) {
46+
if (!logger.isLoggable(level)) {
47+
return;
48+
}
49+
logger.log(level, message.replace("{Elapsed}", formatElapsed(startNanos)));
50+
}
51+
52+
/**
53+
* Logs a timing message at the given level with an exception.
54+
*
55+
* @param logger
56+
* the logger to use
57+
* @param level
58+
* the log level
59+
* @param exception
60+
* the exception, may be {@code null}
61+
* @param message
62+
* the message template
63+
* @param startNanos
64+
* the start time from {@link System#nanoTime()}
65+
*/
66+
static void logTiming(Logger logger, Level level, Throwable exception, String message, long startNanos) {
67+
if (!logger.isLoggable(level)) {
68+
return;
69+
}
70+
String formatted = message.replace("{Elapsed}", formatElapsed(startNanos));
71+
if (exception != null) {
72+
logger.log(level, formatted, exception);
73+
} else {
74+
logger.log(level, formatted);
75+
}
76+
}
77+
}

‎src/main/java/com/github/copilot/sdk/SessionRequestBuilder.java‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -111,6 +111,7 @@ static CreateSessionRequest buildCreateRequest(SessionConfig config, String sess
111111
request.setAvailableTools(config.getAvailableTools());
112112
request.setExcludedTools(config.getExcludedTools());
113113
request.setProvider(config.getProvider());
114+
request.setEnableSessionTelemetry(config.getEnableSessionTelemetry());
114115
request.setRequestUserInput(config.getOnUserInputRequest() != null ? true : null);
115116
request.setHooks(config.getHooks() != null && config.getHooks().hasHooks() ? true : null);
116117
request.setWorkingDirectory(config.getWorkingDirectory());
@@ -187,6 +188,7 @@ static ResumeSessionRequest buildResumeRequest(String sessionId, ResumeSessionCo
187188
request.setAvailableTools(config.getAvailableTools());
188189
request.setExcludedTools(config.getExcludedTools());
189190
request.setProvider(config.getProvider());
191+
request.setEnableSessionTelemetry(config.getEnableSessionTelemetry());
190192
request.setRequestUserInput(config.getOnUserInputRequest() != null ? true : null);
191193
request.setHooks(config.getHooks() != null && config.getHooks().hasHooks() ? true : null);
192194
request.setWorkingDirectory(config.getWorkingDirectory());

‎src/main/java/com/github/copilot/sdk/json/CreateSessionRequest.java‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,9 @@ public final class CreateSessionRequest {
5252
@JsonProperty("provider")
5353
private ProviderConfig provider;
5454

55+
@JsonProperty("enableSessionTelemetry")
56+
private Boolean enableSessionTelemetry;
57+
5558
@JsonProperty("requestPermission")
5659
private Boolean requestPermission;
5760

@@ -207,6 +210,18 @@ public void setProvider(ProviderConfig provider) {
207210
this.provider = provider;
208211
}
209212

213+
/** Gets enable session telemetry flag. @return the flag */
214+
public Boolean getEnableSessionTelemetry() {
215+
return enableSessionTelemetry;
216+
}
217+
218+
/**
219+
* Sets enable session telemetry flag. @param enableSessionTelemetry the flag
220+
*/
221+
public void setEnableSessionTelemetry(Boolean enableSessionTelemetry) {
222+
this.enableSessionTelemetry = enableSessionTelemetry;
223+
}
224+
210225
/** Gets request permission flag. @return the flag */
211226
public Boolean getRequestPermission() {
212227
return requestPermission;

‎src/main/java/com/github/copilot/sdk/json/ResumeSessionConfig.java‎

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,7 @@ public class ResumeSessionConfig {
4343
private List<String> availableTools;
4444
private List<String> excludedTools;
4545
private ProviderConfig provider;
46+
private Boolean enableSessionTelemetry;
4647
private String reasoningEffort;
4748
private ModelCapabilitiesOverride modelCapabilities;
4849
private PermissionHandler onPermissionRequest;
@@ -229,6 +230,38 @@ public ResumeSessionConfig setProvider(ProviderConfig provider) {
229230
return this;
230231
}
231232

233+
/**
234+
* Enables or disables internal session telemetry for this session. When
235+
* {@code false}, disables session telemetry. When {@code null} (the default) or
236+
* {@code true}, telemetry is enabled for GitHub-authenticated sessions. When a
237+
* custom {@link ProviderConfig} (BYOK) is configured, session telemetry is
238+
* always disabled regardless of this setting. This is independent of
239+
* {@link com.github.copilot.sdk.json.CopilotClientOptions#getTelemetry()
240+
* CopilotClientOptions.Telemetry}, which configures OpenTelemetry export for
241+
* observability.
242+
*
243+
* @return whether session telemetry is enabled
244+
*/
245+
public Boolean getEnableSessionTelemetry() {
246+
return enableSessionTelemetry;
247+
}
248+
249+
/**
250+
* Enables or disables internal session telemetry for this session. When
251+
* {@code false}, disables session telemetry. When {@code null} (the default) or
252+
* {@code true}, telemetry is enabled for GitHub-authenticated sessions. When a
253+
* custom {@link ProviderConfig} (BYOK) is configured, session telemetry is
254+
* always disabled regardless of this setting.
255+
*
256+
* @param enableSessionTelemetry
257+
* whether to enable session telemetry
258+
* @return this config for method chaining
259+
*/
260+
public ResumeSessionConfig setEnableSessionTelemetry(Boolean enableSessionTelemetry) {
261+
this.enableSessionTelemetry = enableSessionTelemetry;
262+
return this;
263+
}
264+
232265
/**
233266
* Gets the reasoning effort level.
234267
*
@@ -781,6 +814,7 @@ public ResumeSessionConfig clone() {
781814
copy.availableTools = this.availableTools != null ? new ArrayList<>(this.availableTools) : null;
782815
copy.excludedTools = this.excludedTools != null ? new ArrayList<>(this.excludedTools) : null;
783816
copy.provider = this.provider;
817+
copy.enableSessionTelemetry = this.enableSessionTelemetry;
784818
copy.reasoningEffort = this.reasoningEffort;
785819
copy.modelCapabilities = this.modelCapabilities;
786820
copy.onPermissionRequest = this.onPermissionRequest;

0 commit comments

Comments
 (0)