diff --git a/src/copilot/copilot-auth.ts b/src/copilot/copilot-auth.ts index 81d6fdf6..89236c75 100644 --- a/src/copilot/copilot-auth.ts +++ b/src/copilot/copilot-auth.ts @@ -14,6 +14,9 @@ import { isCopilotApiInstalled as checkInstalled, getCopilotApiBinPath, } from './copilot-package-manager'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('copilot:auth'); /** * Get the path to copilot-api's GitHub token file. @@ -108,6 +111,10 @@ export async function getCopilotDebugInfo(): Promise { export async function checkAuthStatus(): Promise { // Fast path: check if token file exists (instant, no subprocess) if (hasTokenFile()) { + logger.stage('auth', 'copilot.auth.token_present', 'Copilot token file present', { + provider: 'copilot', + method: 'token_file', + }); return { authenticated: true }; } @@ -116,9 +123,20 @@ export async function checkAuthStatus(): Promise { const debugInfo = await getCopilotDebugInfo(); if (debugInfo?.authenticated) { + logger.stage('auth', 'copilot.auth.debug_ok', 'Copilot reports authenticated via debug', { + provider: 'copilot', + method: 'debug', + }); return { authenticated: true }; } + logger.stage( + 'auth', + 'copilot.auth.unauthenticated', + 'Copilot is not authenticated', + { provider: 'copilot' }, + { level: 'warn' } + ); return { authenticated: false, }; @@ -149,6 +167,11 @@ export function startAuthFlow(): Promise { console.log('[i] Starting GitHub authentication for Copilot...'); console.log(''); + const startedAt = Date.now(); + logger.stage('auth', 'copilot.auth.start', 'Starting Copilot OAuth device flow', { + provider: 'copilot', + }); + const proc = spawn(binPath, ['auth'], { stdio: ['ignore', 'pipe', 'pipe'], shell: process.platform === 'win32', @@ -185,8 +208,22 @@ export function startAuthFlow(): Promise { proc.on('close', (code) => { 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 }); } else { + logger.stage( + 'cleanup', + 'copilot.auth.failed', + 'Copilot OAuth device flow failed', + { provider: 'copilot', exitCode: code }, + { level: 'error', latencyMs: Date.now() - startedAt } + ); resolve({ success: false, error: `Authentication failed with exit code ${code}`, @@ -197,6 +234,17 @@ export function startAuthFlow(): Promise { }); 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({ success: false, error: `Failed to start auth: ${err.message}`, diff --git a/src/copilot/copilot-daemon.ts b/src/copilot/copilot-daemon.ts index 4ec2d75b..9214f02f 100644 --- a/src/copilot/copilot-daemon.ts +++ b/src/copilot/copilot-daemon.ts @@ -14,6 +14,9 @@ import { CopilotConfig, DEFAULT_COPILOT_CONFIG } from '../config/unified-config- import { loadOrCreateUnifiedConfig } from '../config/unified-config-loader'; import { getCopilotDir, getCopilotApiBinPath } from './copilot-package-manager'; import { verifyProcessOwnership } from '../cursor/daemon-process-ownership'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('copilot:daemon'); const DAEMON_HEALTH_MARKER = 'server running'; const MIN_PORT = 1; @@ -166,6 +169,10 @@ export async function startDaemon( // Check if already running 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 }; } @@ -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) => { let proc: ChildProcess; let resolved = false; @@ -198,6 +212,27 @@ export async function startDaemon( } if (!result.success) { 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); }; @@ -326,6 +361,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string } } // Send SIGTERM to the process + logger.stage('cleanup', 'copilot.daemon.stop', 'Sending SIGTERM to Copilot daemon', { + provider: 'copilot', + pid, + }); process.kill(pid, 'SIGTERM'); // Wait for process to exit (up to 5 seconds) diff --git a/src/copilot/copilot-executor.ts b/src/copilot/copilot-executor.ts index b1ed44b4..b7d96962 100644 --- a/src/copilot/copilot-executor.ts +++ b/src/copilot/copilot-executor.ts @@ -35,6 +35,9 @@ import { resolveImageAnalysisRuntimeStatus, } from '../utils/hooks'; import { stripClaudeCodeEnv } from '../utils/shell-executor'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('copilot:executor'); interface CopilotImageAnalysisDeps { ensureCliproxyService: typeof ensureCliproxyService; @@ -185,6 +188,12 @@ export async function executeCopilotProfile( ): Promise { 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) { warnings.forEach(({ message }) => console.log(warn(message))); console.log( @@ -216,6 +225,10 @@ export async function executeCopilotProfile( // Check authentication const authStatus = await checkAuthStatus(); + logger.stage('auth', 'copilot.execute.auth_check', 'Checked Copilot auth status', { + provider: 'copilot', + authenticated: authStatus.authenticated, + }); if (!authStatus.authenticated) { console.error(fail('Not authenticated with GitHub.')); console.error(''); @@ -289,6 +302,7 @@ export async function executeCopilotProfile( console.log(''); // Spawn Claude CLI + const spawnStartedAt = Date.now(); return new Promise((resolve) => { const imageAnalysisArgs = imageAnalysisMcpReady ? appendThirdPartyImageAnalysisToolArgs(claudeArgs) @@ -302,6 +316,11 @@ export async function executeCopilotProfile( claudeConfigDir, }); + logger.stage('dispatch', 'copilot.execute.spawn', 'Spawning Claude via Copilot proxy', { + provider: 'copilot', + argCount: launchArgs.length, + }); + const proc = spawn(claudeCliPath, launchArgs, { stdio: 'inherit', env: { ...env, ...traceEnv }, @@ -309,10 +328,28 @@ export async function executeCopilotProfile( }); 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); }); 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}`)); resolve(1); }); diff --git a/src/cursor/cursor-daemon.ts b/src/cursor/cursor-daemon.ts index 697b6df0..5c58b712 100644 --- a/src/cursor/cursor-daemon.ts +++ b/src/cursor/cursor-daemon.ts @@ -12,8 +12,11 @@ import * as http from 'http'; import type { CursorDaemonConfig, CursorDaemonStatus } from './types'; import { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; import { verifyDaemonOwnership } from './daemon-process-ownership'; +import { createLogger } from '../services/logging'; export { getPidFromFile, writePidToFile, removePidFile } from './cursor-daemon-pid'; +const logger = createLogger('cursor:daemon'); + /** * Resolve daemon entrypoint candidates for current runtime. * - Dist runtime always uses JS artifact. @@ -125,6 +128,10 @@ export async function startDaemon( ): Promise<{ success: boolean; pid?: number; error?: string }> { // Check if already running 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 }; } @@ -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) => { let proc: ChildProcess; let resolved = false; @@ -149,7 +163,30 @@ export async function startDaemon( if (resolved) return; resolved = true; 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); }; @@ -270,6 +307,10 @@ export async function stopDaemon(): Promise<{ success: boolean; error?: string } } // Send SIGTERM to the process + logger.stage('cleanup', 'cursor.daemon.stop', 'Sending SIGTERM to Cursor daemon', { + provider: 'cursor', + pid, + }); process.kill(pid, 'SIGTERM'); // Wait for process to exit (up to 5 seconds) diff --git a/src/cursor/cursor-executor.ts b/src/cursor/cursor-executor.ts index d7344be0..c4c2197b 100644 --- a/src/cursor/cursor-executor.ts +++ b/src/cursor/cursor-executor.ts @@ -12,6 +12,9 @@ import { type CursorApiCredentials, } from './cursor-protobuf-schema.js'; import { buildCursorConnectHeaders, generateCursorChecksum } from './cursor-client-policy.js'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('cursor:executor'); import { CursorConnectFrameError, @@ -272,6 +275,13 @@ export class CursorExecutor { const headers = this.buildHeaders(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 { // Streaming requests use incremental HTTP/2 → SSE pipeline if (stream) { @@ -294,6 +304,13 @@ export class CursorExecutor { if (response.status !== 200) { 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( JSON.stringify({ error: { @@ -311,12 +328,31 @@ export class CursorExecutor { } 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 }; } 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( JSON.stringify({ error: { - message: (error as Error).message, + message: err.message, type: 'connection_error', code: '', }, diff --git a/src/glmt/glmt-proxy.ts b/src/glmt/glmt-proxy.ts index f493ba3e..41696b56 100644 --- a/src/glmt/glmt-proxy.ts +++ b/src/glmt/glmt-proxy.ts @@ -23,6 +23,9 @@ import * as https from 'https'; import { GlmtTransformer } from './glmt-transformer'; import { SSEParser } from './sse-parser'; import { DeltaAccumulator } from './delta-accumulator'; +import { createLogger } from '../services/logging'; + +const logger = createLogger('glmt:proxy'); interface GlmtProxyConfig { verbose?: boolean; @@ -137,6 +140,10 @@ export class GlmtProxy { this.server.listen(0, '127.0.0.1', () => { const address = this.server?.address(); 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 console.log(`PROXY_READY:${this.port}`); @@ -448,6 +455,14 @@ export class GlmtProxy { lastError = err; 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) { console.error( `[glmt-proxy] Rate limited, retry ${attempt + 1}/${this.retryConfig.maxRetries} after ${Math.round(delay)}ms` diff --git a/src/glmt/glmt-transformer.ts b/src/glmt/glmt-transformer.ts index 1886f05a..72c4c63e 100644 --- a/src/glmt/glmt-transformer.ts +++ b/src/glmt/glmt-transformer.ts @@ -127,9 +127,13 @@ export class GlmtTransformer { return anthropicResponse; } catch (error) { const err = error as Error; - this.logger.error('response.transform_failed', 'GLMT response transformation failed', { - message: err.message, - }); + this.logger.stage( + '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); return { id: 'msg_error_' + Date.now(),