diff --git a/src/main/daemon/daemon-pty-adapter-wsl-distro-loss.test.ts b/src/main/daemon/daemon-pty-adapter-wsl-distro-loss.test.ts index 97bd84d5115..b5522ece232 100644 --- a/src/main/daemon/daemon-pty-adapter-wsl-distro-loss.test.ts +++ b/src/main/daemon/daemon-pty-adapter-wsl-distro-loss.test.ts @@ -2,10 +2,11 @@ import { mkdtempSync, rmSync } from 'node:fs' import { tmpdir } from 'node:os' import { join } from 'node:path' -import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import { afterEach, beforeEach, describe, expect, it, onTestFinished, vi } from 'vitest' import type { WslRunningDistrosRead } from '../wsl-background-distro-gate' import type { DaemonPtyAdapter } from './daemon-pty-adapter' import type { DaemonServer } from './daemon-server' +import { setActiveSink } from '../observability/tracer' import { HistoryManager } from './history-manager' import { WslBridgeBootIdentity } from './daemon-wsl-bridge-boot-identity' import { @@ -129,6 +130,13 @@ describe('a WSL bridge pane exit', () => { it('logs what the running list said, so a run can tell host loss from a raced reboot', async () => { const info = vi.spyOn(console, 'info').mockImplementation(() => {}) + const spans: unknown[] = [] + setActiveSink({ + push: (span) => spans.push(span), + flush: () => {}, + close: () => {} + }) + onTestFinished(() => setActiveSink(null)) for (const [distros, verdict] of [ [[], 'lost'], [['Ubuntu'], 'running'] @@ -145,6 +153,12 @@ describe('a WSL bridge pane exit', () => { ) ) ) + // Kept in the local trace too: a packaged build keeps no console (verify-18). + expect(spans.at(-1)).toMatchObject({ + name: 'wsl.bridge-exit', + attributes: { verdict, code: 1 } + }) + expect(JSON.stringify(spans.at(-1))).not.toContain('Ubuntu') } }) diff --git a/src/main/daemon/daemon-pty-adapter-wsl-sleep-cwd.test.ts b/src/main/daemon/daemon-pty-adapter-wsl-sleep-cwd.test.ts index 27dcdf806ee..be388c6c594 100644 --- a/src/main/daemon/daemon-pty-adapter-wsl-sleep-cwd.test.ts +++ b/src/main/daemon/daemon-pty-adapter-wsl-sleep-cwd.test.ts @@ -3,6 +3,7 @@ import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' import { join } from 'node:path' import { readFileSync, rmSync } from 'node:fs' import { DaemonPtyAdapter } from './daemon-pty-adapter' +import { setActiveSink } from '../observability/tracer' import type { DaemonServer } from './daemon-server' import { getHistorySessionDirName } from './history-paths' import { createMockSubprocess, startDaemonAdapterHarness } from './daemon-pty-adapter-test-harness' @@ -88,11 +89,21 @@ describe('a sleeping bridge WSL pane keeps its shell folder', () => { rows: 24, cwd: WSL_CWD, env: { ORCA_PANE_KEY: PANE_KEY }, - sessionId: 'repo::/repo@@spawned' + sessionId: 'repo::/home/jin/private-repo@@spawned' }) const info = vi.spyOn(console, 'info').mockImplementation(() => {}) - await adapter.shutdown(id, { immediate: true, keepHistory: true }) + const spans: unknown[] = [] + setActiveSink({ + push: (span) => spans.push(span), + flush: () => {}, + close: () => {} + }) + try { + await adapter.shutdown(id, { immediate: true, keepHistory: true }) + } finally { + setActiveSink(null) + } expect(readRows).toHaveBeenCalledWith('Ubuntu', expect.any(Number), { running: true }) expect(checkpointCwd(id)).toBe(`${WSL_CWD}\\deep\\er`) @@ -101,10 +112,29 @@ describe('a sleeping bridge WSL pane keeps its shell folder', () => { .filter((line) => line.includes('Sleep folder')) // One line per Sleep, naming the branch, what the distro returned and whether a folder came back. expect(lines).toHaveLength(1) - expect(lines[0]).toContain(`[history] Sleep folder for ${id}: wsl probe (budget `) + expect(lines[0]).toContain(`[history] Sleep folder for …@@spawned: wsl probe (budget `) expect(lines[0]).toContain( `rows 2, shells 1), distro Ubuntu, pane ${PANE_KEY}, live true, folder found in ` ) + // verify-18 (b): a packaged build keeps no console, so the same line goes to the local trace. + expect(spans).toContainEqual( + expect.objectContaining({ + name: 'wsl.sleep-folder', + attributes: expect.objectContaining({ + line: lines[0].replace(', distro Ubuntu', ''), + probe: 'wsl', + rows: 2, + shells: 1, + timedOut: false, + folderFound: true + }) + }) + ) + // The trace persists, so it names neither the worktree path in the session id nor the distro. + const persisted = JSON.stringify(spans) + for (const segment of ['home', 'jin', 'private-repo', 'Ubuntu']) { + expect(persisted).not.toContain(segment) + } }) // awin verify-9: panes cd'd before a relaunch and slept before the window reopened them diff --git a/src/main/daemon/daemon-pty-adapter.ts b/src/main/daemon/daemon-pty-adapter.ts index 19b614e34b7..0529bdf45cd 100644 --- a/src/main/daemon/daemon-pty-adapter.ts +++ b/src/main/daemon/daemon-pty-adapter.ts @@ -6,6 +6,7 @@ import { import { FENCED_TERMINATION_PROTOCOL_VERSION } from './daemon-protocol-version' import { emitPtyListeners, createPtyExitPayload } from './daemon-pty-listener-emission' import type { DaemonPtyRouterExitEvent } from './daemon-pty-router-events' +import { logWslPaneDiagnostic } from './daemon-wsl-diagnostic-log' import { classifyWslBridgeExit, WSL_DISTRO_LOSS_EXIT_CODE } from './daemon-wsl-bridge-exit' import { isProvenProcessExit } from '../../shared/terminal-exit-cause' import { DaemonPtyDaemonRecovery } from './daemon-pty-daemon-recovery' @@ -258,8 +259,14 @@ export class DaemonPtyAdapter extends DaemonPtyDaemonRecovery implements IPtyPro ) // Lost, or booted again since the spawn, keeps the tab; an unanswered check reads as an exit. // The code shows a verify run which codes a terminate yields. - console.info( - `[pty] WSL bridge exit: ${verdict} (distro ${wslDistro}, code ${exit.code}, probe ${Math.round(performance.now() - exitAt)}ms)` + const probeMs = Math.round(performance.now() - exitAt) + logWslPaneDiagnostic( + 'wsl.bridge-exit', + { + console: `[pty] WSL bridge exit: ${verdict} (distro ${wslDistro}, code ${exit.code}, probe ${probeMs}ms)`, + trace: `[pty] WSL bridge exit: ${verdict} (code ${exit.code}, probe ${probeMs}ms)` + }, + { verdict, code: exit.code, probeMs } ) // A spawn that replaced this incarnation meanwhile owns the session now. const current = this.sessionIncarnations.get(sessionId) diff --git a/src/main/daemon/daemon-pty-session-control.ts b/src/main/daemon/daemon-pty-session-control.ts index 9e861909097..7ffc85b46fc 100644 --- a/src/main/daemon/daemon-pty-session-control.ts +++ b/src/main/daemon/daemon-pty-session-control.ts @@ -8,7 +8,7 @@ import { remainingDaemonRequestTimeoutMs } from './daemon-request-deadline' import { readDaemonLiveSleepCwd } from './daemon-live-sleep-cwd' import type { ColdRestoreInfo } from './history-reader' import { normalizeWslColdRestoreCwd } from './wsl-cold-restore-cwd' -import { describeSleepFolderRead, readDaemonWslSleepCwdWithFacts } from './daemon-wsl-sleep-cwd' +import { logSleepFolderRead, readDaemonWslSleepCwdWithFacts } from './daemon-wsl-sleep-cwd' import * as unlistedSession from './daemon-unlisted-session' import { SessionNotFoundError, type ListSessionsResult } from './types' import { resolveSafePtyDefaultCwd } from '../providers/pty-default-cwd' @@ -153,14 +153,13 @@ export abstract class DaemonPtySessionControl extends DaemonPtySessionInput { : { cwd: live ? await readDaemonLiveSleepCwd(this.client, id, opts.deadlineMs) : null } const sleepCwd = read.cwd // Device runs need to see why a WSL pane woke at its spawn folder (awin 5e). - console.info( - describeSleepFolderRead(id, read, { - wslDistro: sleepWslDistro, - paneKey: sleepPaneKey, - live, - elapsedMs: Date.now() - startedAt - }) - ) + const sleepFolder = { + wslDistro: sleepWslDistro, + paneKey: sleepPaneKey, + live, + elapsedMs: Date.now() - startedAt + } + logSleepFolderRead(id, read, sleepFolder) const committed = await this.runExclusiveCheckpoint( async () => { // Set inside: a caller past its deadline leaves this checkpoint running without it. diff --git a/src/main/daemon/daemon-wsl-diagnostic-log.ts b/src/main/daemon/daemon-wsl-diagnostic-log.ts new file mode 100644 index 00000000000..3a6b9ffc84a --- /dev/null +++ b/src/main/daemon/daemon-wsl-diagnostic-log.ts @@ -0,0 +1,19 @@ +/** + * Device diagnosis of WSL panes: console output is not kept on a packaged build, so each line + * also goes to the local trace file (main.trace.ndjson, kept unless diagnostics are turned off). + */ +import { startSpan } from '../observability/tracer' + +/** `trace` is the persisted line, so it must carry no paths or distro names. */ +export function logWslPaneDiagnostic( + name: 'wsl.sleep-folder' | 'wsl.bridge-exit', + line: { console: string; trace: string }, + attributes: Record +): void { + console.info(line.console) + try { + startSpan(name, { attributes: { line: line.trace, ...attributes } }).end() + } catch { + // Optional diagnostics must never fail a Sleep or an exit. + } +} diff --git a/src/main/daemon/daemon-wsl-sleep-cwd.ts b/src/main/daemon/daemon-wsl-sleep-cwd.ts index 988bf3775ae..9e5200dfb59 100644 --- a/src/main/daemon/daemon-wsl-sleep-cwd.ts +++ b/src/main/daemon/daemon-wsl-sleep-cwd.ts @@ -1,7 +1,9 @@ /** Bridge WSL bash lacks OSC 7; read its shell folder before Sleep so wake avoids the spawn folder. Failures retain the old fallback. */ import { toWindowsWslUncPath } from '../../shared/wsl-paths' +import { redactPtyIdForDiagnostics } from '../../shared/pty-delivery-diagnostics' import { paneShells, readWslGuestPaneProcesses } from '../wsl/wsl-guest-pane-processes' import { teardownReadBudgetMs } from './daemon-request-deadline' +import { logWslPaneDiagnostic } from './daemon-wsl-diagnostic-log' // Reserve teardown time for the final checkpoint and kill when a distro does not answer. const READ_BUDGET_MS = 3_000 @@ -90,11 +92,45 @@ export async function readDaemonWslQuitCwds( export function describeSleepFolderRead( sessionId: string, read: DaemonWslSleepCwdRead | { cwd: string | null }, - pane: { wslDistro?: string; paneKey?: string; live: boolean; elapsedMs: number } + pane: { wslDistro?: string; paneKey?: string; live: boolean; elapsedMs: number }, + opts: { withDistro: boolean } = { withDistro: true } ): string { const probe = 'rows' in read ? `wsl probe (budget ${read.budgetMs}ms, rows ${read.rows ?? 'none'}${read.timedOut ? ' timed out' : ''}, shells ${read.shells ?? 'none'})` : 'live probe' - return `[history] Sleep folder for ${sessionId}: ${probe}, distro ${pane.wslDistro ?? 'unknown'}, pane ${pane.paneKey ?? 'unknown'}, live ${pane.live}, folder ${read.cwd ? 'found' : 'not found'} in ${pane.elapsedMs}ms` + // The session id embeds the worktree path; the distro name can be personal (trace only). + const distro = opts.withDistro ? `, distro ${pane.wslDistro ?? 'unknown'}` : '' + return `[history] Sleep folder for ${redactPtyIdForDiagnostics(sessionId)}: ${probe}${distro}, pane ${pane.paneKey ?? 'unknown'}, live ${pane.live}, folder ${read.cwd ? 'found' : 'not found'} in ${pane.elapsedMs}ms` +} + +export function logSleepFolderRead( + sessionId: string, + read: DaemonWslSleepCwdRead | { cwd: string | null }, + pane: { wslDistro?: string; paneKey?: string; live: boolean; elapsedMs: number } +): void { + logWslPaneDiagnostic( + 'wsl.sleep-folder', + { + console: describeSleepFolderRead(sessionId, read, pane), + trace: describeSleepFolderRead(sessionId, read, pane, { withDistro: false }) + }, + sleepFolderAttributes(read, pane) + ) +} + +/** The same facts as the line, as fields a trace reader can filter on. */ +function sleepFolderAttributes( + read: DaemonWslSleepCwdRead | { cwd: string | null }, + pane: { live: boolean; elapsedMs: number } +): Record { + return { + probe: 'rows' in read ? 'wsl' : 'live', + live: pane.live, + folderFound: read.cwd !== null, + elapsedMs: pane.elapsedMs, + ...('rows' in read + ? { rows: read.rows, shells: read.shells, timedOut: read.timedOut, budgetMs: read.budgetMs } + : {}) + } }