Merge pull request #171 from github/copilot/reference-impl-sync-6-new-commits

Port enableSessionTelemetry option and SDK tracing diagnostics from reference implementation

Author: edburns

.lastmerge

@@ -1 +1 @@
-06bfc5d41d72b76527456dee0bd78fe4697bac86
+066a69c1e849adf1bd98564ab1b52316ec471182

pom.xml

@@ -94,7 +94,7 @@
             reference-impl-sync workflow and deal with the subsequent
             PR.
         -->
-        <readonly-copilot-sdk-ref-impl-version-from-lastmerge-file-updated-by-reference-impl-sync>^1.0.43-0</readonly-copilot-sdk-ref-impl-version-from-lastmerge-file-updated-by-reference-impl-sync>
+        <readonly-copilot-sdk-ref-impl-version-from-lastmerge-file-updated-by-reference-impl-sync>^1.0.44-2</readonly-copilot-sdk-ref-impl-version-from-lastmerge-file-updated-by-reference-impl-sync>
 
     </properties>
 
@@ -327,9 +327,8 @@
                         This handles intermittent failures in E2E tests (e.g.,
                         CompactionTest) where snapshot matching can be sensitive
                         to non-deterministic compaction behaviour.
-                        TODO: Fix the root cause of CompactionTest flakiness
-                        (snapshot mismatch after compaction) so this retry is
-                        no longer needed.
+                        Revisit this once this issue is successfully resolved.
+                        https://github.com/github/copilot-sdk/issues/1227 
                     -->
                     <rerunFailingTestsCount>2</rerunFailingTestsCount>
                     <systemPropertyVariables>
@@ -346,6 +345,30 @@
                         <COPILOT_CLI_PATH>${copilot.cli.path}</COPILOT_CLI_PATH>
                     </environmentVariables>
                 </configuration>
+                <executions>
+                    <!--
+                        Run multi-client session resume tests in isolation BEFORE the
+                        main suite. These tests pass reliably alone but can time out
+                        when run after other E2E tests due to harness state leakage.
+                    -->
+                    <execution>
+                        <id>isolated-resume-tests</id>
+                        <phase>test</phase>
+                        <goals>
+                            <goal>test</goal>
+                        </goals>
+                        <configuration>
+                            <groups>isolated-resume</groups>
+                        </configuration>
+                    </execution>
+                    <!-- Exclude the isolated resume tests from the main run -->
+                    <execution>
+                        <id>default-test</id>
+                        <configuration>
+                            <excludedGroups>isolated-resume</excludedGroups>
+                        </configuration>
+                    </execution>
+                </executions>
             </plugin>
             <!-- Add src/generated/java as an additional source root -->
             <plugin>

scripts/codegen/package-lock.json

@@ -7,7 +7,7 @@
     "generate:java": "tsx java.ts"
   },
   "dependencies": {
-    "@github/copilot": "^1.0.43-0",
+    "@github/copilot": "^1.0.44-2",
     "json-schema": "^0.4.0",
     "tsx": "^4.20.6"
   }

scripts/codegen/package.json

@@ -188,6 +188,7 @@ private CompletableFuture<Connection> startCore() {
 
     private Connection startCoreBody() {
         Process process = null;
+        long startNanos = System.nanoTime();
         try {
             JsonRpcClient rpc;
 
@@ -202,6 +203,9 @@ private Connection startCoreBody() {
                         processInfo.port());
             }
 
+            LoggingHelpers.logTiming(LOG, Level.FINE, "CopilotClient.start transport setup complete. Elapsed={Elapsed}",
+                    startNanos);
+
             Connection connection = new Connection(rpc, process, new ServerRpc(rpc::invoke));
 
             // Register handlers for server-to-client calls
@@ -211,10 +215,16 @@ private Connection startCoreBody() {
 
             // Verify protocol version
             verifyProtocolVersion(connection);
+            LoggingHelpers.logTiming(LOG, Level.FINE,
+                    "CopilotClient.start protocol verification complete. Elapsed={Elapsed}", startNanos);
 
-            LOG.info("Copilot client connected");
+            LoggingHelpers.logTiming(LOG, Level.FINE, "CopilotClient.start complete. Elapsed={Elapsed}", startNanos);
             return connection;
         } catch (Exception e) {
+            if (!(e instanceof java.util.concurrent.CancellationException)) {
+                LoggingHelpers.logTiming(LOG, Level.WARNING, e, "CopilotClient.start failed. Elapsed={Elapsed}",
+                        startNanos);
+            }
             // Clean up the spawned process if connection setup failed
             if (process != null) {
                 cleanupCliProcess(process);
@@ -417,18 +427,23 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
                             + "new SessionConfig().setOnPermissionRequest(PermissionHandler.APPROVE_ALL)"));
         }
         return ensureConnected().thenCompose(connection -> {
+            long totalNanos = System.nanoTime();
             // Pre-generate session ID so the session can be registered before the RPC call,
             // ensuring no events emitted by the CLI during creation are lost.
             String sessionId = config.getSessionId() != null
                     ? config.getSessionId()
                     : java.util.UUID.randomUUID().toString();
 
+            long setupNanos = System.nanoTime();
             var session = new CopilotSession(sessionId, connection.rpc);
             if (options.getExecutor() != null) {
                 session.setExecutor(options.getExecutor());
             }
             SessionRequestBuilder.configureSession(session, config);
             sessions.put(sessionId, session);
+            LoggingHelpers.logTiming(LOG, Level.FINE,
+                    "CopilotClient.createSession local setup complete. Elapsed={Elapsed}, SessionId=" + sessionId,
+                    setupNanos);
 
             // Extract transform callbacks from the system message config.
             // Callbacks are registered with the session; a wire-safe copy of the
@@ -444,7 +459,12 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
                 request.setSystemMessage(extracted.wireSystemMessage());
             }
 
+            long rpcNanos = System.nanoTime();
             return connection.rpc.invoke("session.create", request, CreateSessionResponse.class).thenApply(response -> {
+                LoggingHelpers.logTiming(LOG, Level.FINE,
+                        "CopilotClient.createSession session creation request completed. Elapsed={Elapsed}, SessionId="
+                                + sessionId,
+                        rpcNanos);
                 session.setWorkspacePath(response.workspacePath());
                 session.setCapabilities(response.capabilities());
                 // If the server returned a different sessionId (e.g. a v2 CLI that ignores
@@ -455,9 +475,13 @@ public CompletableFuture<CopilotSession> createSession(SessionConfig config) {
                     session.setActiveSessionId(returnedId);
                     sessions.put(returnedId, session);
                 }
+                LoggingHelpers.logTiming(LOG, Level.FINE,
+                        "CopilotClient.createSession complete. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
                 return session;
             }).exceptionally(ex -> {
                 sessions.remove(sessionId);
+                LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
+                        "CopilotClient.createSession failed. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
                 throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
             });
         });
@@ -496,13 +520,18 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
                             + "new ResumeSessionConfig().setOnPermissionRequest(PermissionHandler.APPROVE_ALL)"));
         }
         return ensureConnected().thenCompose(connection -> {
+            long totalNanos = System.nanoTime();
             // Register the session before the RPC call to avoid missing early events.
+            long setupNanos = System.nanoTime();
             var session = new CopilotSession(sessionId, connection.rpc);
             if (options.getExecutor() != null) {
                 session.setExecutor(options.getExecutor());
             }
             SessionRequestBuilder.configureSession(session, config);
             sessions.put(sessionId, session);
+            LoggingHelpers.logTiming(LOG, Level.FINE,
+                    "CopilotClient.resumeSession local setup complete. Elapsed={Elapsed}, SessionId=" + sessionId,
+                    setupNanos);
 
             // Extract transform callbacks from the system message config.
             var extracted = SessionRequestBuilder.extractTransformCallbacks(config.getSystemMessage());
@@ -515,7 +544,12 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
                 request.setSystemMessage(extracted.wireSystemMessage());
             }
 
+            long rpcNanos = System.nanoTime();
             return connection.rpc.invoke("session.resume", request, ResumeSessionResponse.class).thenApply(response -> {
+                LoggingHelpers.logTiming(LOG, Level.FINE,
+                        "CopilotClient.resumeSession session resume request completed. Elapsed={Elapsed}, SessionId="
+                                + sessionId,
+                        rpcNanos);
                 session.setWorkspacePath(response.workspacePath());
                 session.setCapabilities(response.capabilities());
                 // If the server returned a different sessionId than what was requested, re-key.
@@ -525,9 +559,13 @@ public CompletableFuture<CopilotSession> resumeSession(String sessionId, ResumeS
                     session.setActiveSessionId(returnedId);
                     sessions.put(returnedId, session);
                 }
+                LoggingHelpers.logTiming(LOG, Level.FINE,
+                        "CopilotClient.resumeSession complete. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
                 return session;
             }).exceptionally(ex -> {
                 sessions.remove(sessionId);
+                LoggingHelpers.logTiming(LOG, Level.WARNING, ex,
+                        "CopilotClient.resumeSession failed. Elapsed={Elapsed}, SessionId=" + sessionId, totalNanos);
                 throw ex instanceof RuntimeException re ? re : new RuntimeException(ex);
             });
         });