feat(providers): instrument copilot, cursor, and glmt across daemons and executors

Provider modules now emit structured stage tags around daemon spawn /
ready / stop, executor invocations, and upstream dispatch. glmt-transformer
gets cleanup-stage error conversion; legacy glmt-proxy adds minimal
listen + retry instrumentation (full per-request stages live in proxy-server
since glmt-proxy is compat-only).

Refs #1141, #1138
This commit is contained in:
Tam Nhu Tran
2026-04-30 13:00:33 -04:00
parent bf8759460d
commit 1ff4329ee4
7 changed files with 225 additions and 5 deletions
+48
View File
@@ -14,6 +14,9 @@ import {
isCopilotApiInstalled as checkInstalled, isCopilotApiInstalled as checkInstalled,
getCopilotApiBinPath, getCopilotApiBinPath,
} from './copilot-package-manager'; } from './copilot-package-manager';
import { createLogger } from '../services/logging';
const logger = createLogger('copilot:auth');
/** /**
* Get the path to copilot-api's GitHub token file. * Get the path to copilot-api's GitHub token file.
@@ -108,6 +111,10 @@ export async function getCopilotDebugInfo(): Promise<CopilotDebugInfo | null> {
export async function checkAuthStatus(): Promise<CopilotAuthStatus> { export async function checkAuthStatus(): Promise<CopilotAuthStatus> {
// Fast path: check if token file exists (instant, no subprocess) // Fast path: check if token file exists (instant, no subprocess)
if (hasTokenFile()) { if (hasTokenFile()) {
logger.stage('auth', 'copilot.auth.token_present', 'Copilot token file present', {
provider: 'copilot',
method: 'token_file',
});
return { authenticated: true }; return { authenticated: true };
} }
@@ -116,9 +123,20 @@ export async function checkAuthStatus(): Promise<CopilotAuthStatus> {
const debugInfo = await getCopilotDebugInfo(); const debugInfo = await getCopilotDebugInfo();
if (debugInfo?.authenticated) { if (debugInfo?.authenticated) {
logger.stage('auth', 'copilot.auth.debug_ok', 'Copilot reports authenticated via debug', {
provider: 'copilot',
method: 'debug',
});
return { authenticated: true }; return { authenticated: true };
} }
logger.stage(
'auth',
'copilot.auth.unauthenticated',
'Copilot is not authenticated',
{ provider: 'copilot' },
{ level: 'warn' }
);
return { return {
authenticated: false, authenticated: false,
}; };
@@ -149,6 +167,11 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
console.log('[i] Starting GitHub authentication for Copilot...'); console.log('[i] Starting GitHub authentication for Copilot...');
console.log(''); console.log('');
const startedAt = Date.now();
logger.stage('auth', 'copilot.auth.start', 'Starting Copilot OAuth device flow', {
provider: 'copilot',
});
const proc = spawn(binPath, ['auth'], { const proc = spawn(binPath, ['auth'], {
stdio: ['ignore', 'pipe', 'pipe'], stdio: ['ignore', 'pipe', 'pipe'],
shell: process.platform === 'win32', shell: process.platform === 'win32',
@@ -185,8 +208,22 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
proc.on('close', (code) => { proc.on('close', (code) => {
if (code === 0) { if (code === 0) {
logger.stage(
'auth',
'copilot.auth.complete',
'Copilot OAuth device flow completed',
{ provider: 'copilot', exitCode: code },
{ latencyMs: Date.now() - startedAt }
);
resolve({ success: true, deviceCode, verificationUrl }); resolve({ success: true, deviceCode, verificationUrl });
} else { } else {
logger.stage(
'cleanup',
'copilot.auth.failed',
'Copilot OAuth device flow failed',
{ provider: 'copilot', exitCode: code },
{ level: 'error', latencyMs: Date.now() - startedAt }
);
resolve({ resolve({
success: false, success: false,
error: `Authentication failed with exit code ${code}`, error: `Authentication failed with exit code ${code}`,
@@ -197,6 +234,17 @@ export function startAuthFlow(): Promise<AuthFlowResult> {
}); });
proc.on('error', (err) => { proc.on('error', (err) => {
logger.stage(
'cleanup',
'copilot.auth.error',
'Failed to start Copilot OAuth process',
{ provider: 'copilot' },
{
level: 'error',
latencyMs: Date.now() - startedAt,
error: { name: err.name, message: err.message },
}
);
resolve({ resolve({
success: false, success: false,
error: `Failed to start auth: ${err.message}`, error: `Failed to start auth: ${err.message}`,
+39
View File
@@ -14,6 +14,9 @@ import { CopilotConfig, DEFAULT_COPILOT_CONFIG } from '../config/unified-config-
import { loadOrCreateUnifiedConfig } from '../config/unified-config-loader'; import { loadOrCreateUnifiedConfig } from '../config/unified-config-loader';
import { getCopilotDir, getCopilotApiBinPath } from './copilot-package-manager'; import { getCopilotDir, getCopilotApiBinPath } from './copilot-package-manager';
import { verifyProcessOwnership } from '../cursor/daemon-process-ownership'; import { verifyProcessOwnership } from '../cursor/daemon-process-ownership';
import { createLogger } from '../services/logging';
const logger = createLogger('copilot:daemon');
const DAEMON_HEALTH_MARKER = 'server running'; const DAEMON_HEALTH_MARKER = 'server running';
const MIN_PORT = 1; const MIN_PORT = 1;
@@ -166,6 +169,10 @@ export async function startDaemon(
// Check if already running // Check if already running
if (await isDaemonRunning(config.port)) { if (await isDaemonRunning(config.port)) {
logger.stage('dispatch', 'copilot.daemon.already_running', 'Copilot daemon already running', {
provider: 'copilot',
port: config.port,
});
return { success: true, pid: getPidFromFile() ?? undefined }; return { success: true, pid: getPidFromFile() ?? undefined };
} }
@@ -185,6 +192,13 @@ export async function startDaemon(
} }
} }
const startedAt = Date.now();
logger.stage('dispatch', 'copilot.daemon.spawn', 'Spawning Copilot daemon', {
provider: 'copilot',
port: config.port,
accountType: config.account_type,
});
return new Promise((resolve) => { return new Promise((resolve) => {
let proc: ChildProcess; let proc: ChildProcess;
let resolved = false; let resolved = false;
@@ -198,6 +212,27 @@ export async function startDaemon(
} }
if (!result.success) { if (!result.success) {
removePidFile(); removePidFile();
logger.stage(
'cleanup',
'copilot.daemon.start_failed',
'Copilot daemon failed to start',
{ provider: 'copilot', port: config.port },
{
level: 'error',
latencyMs: Date.now() - startedAt,
error: result.error
? { name: 'CopilotDaemonStartError', message: result.error }
: undefined,
}
);
} else {
logger.stage(
'upstream',
'copilot.daemon.ready',
'Copilot daemon is ready',
{ provider: 'copilot', port: config.port, pid: result.pid },
{ latencyMs: Date.now() - startedAt }
);
} }
resolve(result); resolve(result);
}; };
@@ -326,6 +361,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string }
} }
// Send SIGTERM to the process // Send SIGTERM to the process
logger.stage('cleanup', 'copilot.daemon.stop', 'Sending SIGTERM to Copilot daemon', {
provider: 'copilot',
pid,
});
process.kill(pid, 'SIGTERM'); process.kill(pid, 'SIGTERM');
// Wait for process to exit (up to 5 seconds) // Wait for process to exit (up to 5 seconds)
+37
View File
@@ -35,6 +35,9 @@ import {
resolveImageAnalysisRuntimeStatus, resolveImageAnalysisRuntimeStatus,
} from '../utils/hooks'; } from '../utils/hooks';
import { stripClaudeCodeEnv } from '../utils/shell-executor'; import { stripClaudeCodeEnv } from '../utils/shell-executor';
import { createLogger } from '../services/logging';
const logger = createLogger('copilot:executor');
interface CopilotImageAnalysisDeps { interface CopilotImageAnalysisDeps {
ensureCliproxyService: typeof ensureCliproxyService; ensureCliproxyService: typeof ensureCliproxyService;
@@ -185,6 +188,12 @@ export async function executeCopilotProfile(
): Promise<number> { ): Promise<number> {
const { config: normalizedConfig, warnings } = normalizeCopilotConfigWithWarnings(config); const { config: normalizedConfig, warnings } = normalizeCopilotConfigWithWarnings(config);
logger.stage('intake', 'copilot.execute.start', 'Starting Copilot profile execution', {
provider: 'copilot',
model: normalizedConfig.model,
port: normalizedConfig.port,
});
if (warnings.length > 0) { if (warnings.length > 0) {
warnings.forEach(({ message }) => console.log(warn(message))); warnings.forEach(({ message }) => console.log(warn(message)));
console.log( console.log(
@@ -216,6 +225,10 @@ export async function executeCopilotProfile(
// Check authentication // Check authentication
const authStatus = await checkAuthStatus(); const authStatus = await checkAuthStatus();
logger.stage('auth', 'copilot.execute.auth_check', 'Checked Copilot auth status', {
provider: 'copilot',
authenticated: authStatus.authenticated,
});
if (!authStatus.authenticated) { if (!authStatus.authenticated) {
console.error(fail('Not authenticated with GitHub.')); console.error(fail('Not authenticated with GitHub.'));
console.error(''); console.error('');
@@ -289,6 +302,7 @@ export async function executeCopilotProfile(
console.log(''); console.log('');
// Spawn Claude CLI // Spawn Claude CLI
const spawnStartedAt = Date.now();
return new Promise((resolve) => { return new Promise((resolve) => {
const imageAnalysisArgs = imageAnalysisMcpReady const imageAnalysisArgs = imageAnalysisMcpReady
? appendThirdPartyImageAnalysisToolArgs(claudeArgs) ? appendThirdPartyImageAnalysisToolArgs(claudeArgs)
@@ -302,6 +316,11 @@ export async function executeCopilotProfile(
claudeConfigDir, claudeConfigDir,
}); });
logger.stage('dispatch', 'copilot.execute.spawn', 'Spawning Claude via Copilot proxy', {
provider: 'copilot',
argCount: launchArgs.length,
});
const proc = spawn(claudeCliPath, launchArgs, { const proc = spawn(claudeCliPath, launchArgs, {
stdio: 'inherit', stdio: 'inherit',
env: { ...env, ...traceEnv }, env: { ...env, ...traceEnv },
@@ -309,10 +328,28 @@ export async function executeCopilotProfile(
}); });
proc.on('close', (code) => { proc.on('close', (code) => {
logger.stage(
'respond',
'copilot.execute.exit',
'Claude process exited (Copilot)',
{ provider: 'copilot', exitCode: code },
{ latencyMs: Date.now() - spawnStartedAt }
);
resolve(code ?? 0); resolve(code ?? 0);
}); });
proc.on('error', (err) => { proc.on('error', (err) => {
logger.stage(
'cleanup',
'copilot.execute.error',
'Failed to spawn Claude (Copilot)',
{ provider: 'copilot' },
{
level: 'error',
latencyMs: Date.now() - spawnStartedAt,
error: { name: err.name, message: err.message },
}
);
console.error(fail(`Failed to start Claude: ${err.message}`)); console.error(fail(`Failed to start Claude: ${err.message}`));
resolve(1); resolve(1);
}); });
+42 -1
View File
@@ -12,8 +12,11 @@ import * as http from 'http';
import type { CursorDaemonConfig, CursorDaemonStatus } from './types'; import type { CursorDaemonConfig, CursorDaemonStatus } from './types';
import { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; import { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid';
import { verifyDaemonOwnership } from './daemon-process-ownership'; import { verifyDaemonOwnership } from './daemon-process-ownership';
import { createLogger } from '../services/logging';
export { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; export { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid';
const logger = createLogger('cursor:daemon');
/** /**
* Resolve daemon entrypoint candidates for current runtime. * Resolve daemon entrypoint candidates for current runtime.
* - Dist runtime always uses JS artifact. * - Dist runtime always uses JS artifact.
@@ -125,6 +128,10 @@ export async function startDaemon(
): Promise<{ success: boolean; pid?: number; error?: string }> { ): Promise<{ success: boolean; pid?: number; error?: string }> {
// Check if already running // Check if already running
if (await isDaemonRunning(config.port)) { if (await isDaemonRunning(config.port)) {
logger.stage('dispatch', 'cursor.daemon.already_running', 'Cursor daemon already running', {
provider: 'cursor',
port: config.port,
});
return { success: true, pid: getPidFromFile() ?? undefined }; return { success: true, pid: getPidFromFile() ?? undefined };
} }
@@ -141,6 +148,13 @@ export async function startDaemon(
}; };
} }
const startedAt = Date.now();
logger.stage('dispatch', 'cursor.daemon.spawn', 'Spawning Cursor daemon', {
provider: 'cursor',
port: config.port,
ghostMode: config.ghost_mode !== false,
});
return new Promise((resolve) => { return new Promise((resolve) => {
let proc: ChildProcess; let proc: ChildProcess;
let resolved = false; let resolved = false;
@@ -149,7 +163,30 @@ export async function startDaemon(
if (resolved) return; if (resolved) return;
resolved = true; resolved = true;
if (checkTimeout) clearTimeout(checkTimeout); if (checkTimeout) clearTimeout(checkTimeout);
if (!result.success) removePidFile(); if (!result.success) {
removePidFile();
logger.stage(
'cleanup',
'cursor.daemon.start_failed',
'Cursor daemon failed to start',
{ provider: 'cursor', port: config.port },
{
level: 'error',
latencyMs: Date.now() - startedAt,
error: result.error
? { name: 'CursorDaemonStartError', message: result.error }
: undefined,
}
);
} else {
logger.stage(
'upstream',
'cursor.daemon.ready',
'Cursor daemon is ready',
{ provider: 'cursor', port: config.port, pid: result.pid },
{ latencyMs: Date.now() - startedAt }
);
}
resolve(result); resolve(result);
}; };
@@ -270,6 +307,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string }
} }
// Send SIGTERM to the process // Send SIGTERM to the process
logger.stage('cleanup', 'cursor.daemon.stop', 'Sending SIGTERM to Cursor daemon', {
provider: 'cursor',
pid,
});
process.kill(pid, 'SIGTERM'); process.kill(pid, 'SIGTERM');
// Wait for process to exit (up to 5 seconds) // Wait for process to exit (up to 5 seconds)
+37 -1
View File
@@ -12,6 +12,9 @@ import {
type CursorApiCredentials, type CursorApiCredentials,
} from './cursor-protobuf-schema.js'; } from './cursor-protobuf-schema.js';
import { buildCursorConnectHeaders, generateCursorChecksum } from './cursor-client-policy.js'; import { buildCursorConnectHeaders, generateCursorChecksum } from './cursor-client-policy.js';
import { createLogger } from '../services/logging';
const logger = createLogger('cursor:executor');
import { import {
CursorConnectFrameError, CursorConnectFrameError,
@@ -272,6 +275,13 @@ export class CursorExecutor {
const headers = this.buildHeaders(credentials); const headers = this.buildHeaders(credentials);
const transformedBody = this.transformRequest(model, body, stream, credentials); const transformedBody = this.transformRequest(model, body, stream, credentials);
const startedAt = Date.now();
logger.stage('upstream', 'cursor.upstream.request', 'Sending Cursor upstream request', {
provider: 'cursor',
model,
stream,
});
try { try {
// Streaming requests use incremental HTTP/2 → SSE pipeline // Streaming requests use incremental HTTP/2 → SSE pipeline
if (stream) { if (stream) {
@@ -294,6 +304,13 @@ export class CursorExecutor {
if (response.status !== 200) { if (response.status !== 200) {
const errorText = response.body?.toString() || 'Unknown error'; const errorText = response.body?.toString() || 'Unknown error';
logger.stage(
'cleanup',
'cursor.upstream.error',
'Cursor upstream returned non-200 status',
{ provider: 'cursor', model, status: response.status },
{ level: 'error', latencyMs: Date.now() - startedAt }
);
const errorResponse = new Response( const errorResponse = new Response(
JSON.stringify({ JSON.stringify({
error: { error: {
@@ -311,12 +328,31 @@ export class CursorExecutor {
} }
const transformedResponse = this.transformProtobufToJSON(response.body, model, body); const transformedResponse = this.transformProtobufToJSON(response.body, model, body);
logger.stage(
'transform',
'cursor.upstream.transformed',
'Cursor response transformed',
{ provider: 'cursor', model },
{ latencyMs: Date.now() - startedAt }
);
return { response: transformedResponse, url, headers, transformedBody: body }; return { response: transformedResponse, url, headers, transformedBody: body };
} catch (error) { } catch (error) {
const err = error as Error;
logger.stage(
'cleanup',
'cursor.upstream.exception',
'Cursor upstream request threw',
{ provider: 'cursor', model },
{
level: 'error',
latencyMs: Date.now() - startedAt,
error: { name: err.name, message: err.message },
}
);
const errorResponse = new Response( const errorResponse = new Response(
JSON.stringify({ JSON.stringify({
error: { error: {
message: (error as Error).message, message: err.message,
type: 'connection_error', type: 'connection_error',
code: '', code: '',
}, },
+15
View File
@@ -23,6 +23,9 @@ import * as https from 'https';
import { GlmtTransformer } from './glmt-transformer'; import { GlmtTransformer } from './glmt-transformer';
import { SSEParser } from './sse-parser'; import { SSEParser } from './sse-parser';
import { DeltaAccumulator } from './delta-accumulator'; import { DeltaAccumulator } from './delta-accumulator';
import { createLogger } from '../services/logging';
const logger = createLogger('glmt:proxy');
interface GlmtProxyConfig { interface GlmtProxyConfig {
verbose?: boolean; verbose?: boolean;
@@ -137,6 +140,10 @@ export class GlmtProxy {
this.server.listen(0, '127.0.0.1', () => { this.server.listen(0, '127.0.0.1', () => {
const address = this.server?.address(); const address = this.server?.address();
this.port = typeof address === 'object' && address ? address.port : 0; this.port = typeof address === 'object' && address ? address.port : 0;
logger.stage('intake', 'glmt.proxy.listening', 'GLMT proxy listening', {
provider: 'glmt',
port: this.port,
});
// Signal parent process // Signal parent process
console.log(`PROXY_READY:${this.port}`); console.log(`PROXY_READY:${this.port}`);
@@ -448,6 +455,14 @@ export class GlmtProxy {
lastError = err; lastError = err;
const delay = this.calculateRetryDelay(attempt, retryAfter); const delay = this.calculateRetryDelay(attempt, retryAfter);
logger.stage(
'upstream',
'glmt.upstream.retry',
'Retrying GLMT upstream after retryable error',
{ provider: 'glmt', attempt: attempt + 1, maxRetries: this.retryConfig.maxRetries },
{ level: 'warn' }
);
if (this.verbose) { if (this.verbose) {
console.error( console.error(
`[glmt-proxy] Rate limited, retry ${attempt + 1}/${this.retryConfig.maxRetries} after ${Math.round(delay)}ms` `[glmt-proxy] Rate limited, retry ${attempt + 1}/${this.retryConfig.maxRetries} after ${Math.round(delay)}ms`
+7 -3
View File
@@ -127,9 +127,13 @@ export class GlmtTransformer {
return anthropicResponse; return anthropicResponse;
} catch (error) { } catch (error) {
const err = error as Error; const err = error as Error;
this.logger.error('response.transform_failed', 'GLMT response transformation failed', { this.logger.stage(
message: err.message, 'cleanup',
}); 'response.transform_failed',
'GLMT response transformation failed',
undefined,
{ level: 'error', error: { name: err.name, message: err.message } }
);
console.error('[glmt-transformer] Response transformation error:', err); console.error('[glmt-transformer] Response transformation error:', err);
return { return {
id: 'msg_error_' + Date.now(), id: 'msg_error_' + Date.now(),