feat: implement background process logging and cleanup

- Add persistent logging for backgrounded shell processes in ~/.gemini/tmp/background-processes
- Implement automatic cleanup of background logs older than 7 days on CLI startup
- Support real-time output syncing to log files for both PTY and child_process execution
- Update UI to indicate log file availability for background tasks
- Add comprehensive unit and integration tests for logging and cleanup logic
This commit is contained in:
galz10
2026-03-04 17:00:48 -08:00
parent fb32db5cd6
commit 127fbf9487
15 changed files with 767 additions and 103 deletions
@@ -0,0 +1,87 @@
/**
* @license
* Copyright 2025 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { describe, it, expect, beforeEach, afterEach } from 'vitest';
import { TestRig } from './test-helper.js';
import fs from 'node:fs';
import path from 'node:path';
describe('Background Shell Output Logging', () => {
let rig: TestRig;
beforeEach(() => {
rig = new TestRig();
});
afterEach(async () => await rig.cleanup());
it('should log background process output to a file', async () => {
await rig.setup('should log background process output to a file', {
settings: { tools: { core: ['run_shell_command'] } },
});
// We use a command that outputs something, then backgrounds, then outputs more.
// Since we're in the test rig, we have to be careful with how we background.
// The run_shell_command tool backgrounds if is_background: true is passed.
const prompt = `Please run the command "echo start && sleep 1 && echo end" in the background and tell me the PID.`;
const result = await rig.run({
args: [prompt],
// approvalMode: 'yolo' is needed to avoid interactive prompt in tests
approvalMode: 'yolo',
});
// Extract PID from result
const cleanResult = result.replace(
// eslint-disable-next-line no-control-regex
/[\u001b\u009b][[()#;?]*(?:[0-9]{1,4}(?:;[0-9]{0,4})*)?[0-9A-ORZcf-nqry=><]/g,
'',
);
const pidMatch = cleanResult.match(/PID.*?\s*(\d+)/i);
expect(pidMatch, `Expected PID in output: ${cleanResult}`).toBeTruthy();
const pid = parseInt(pidMatch![1], 10);
const logDir = path.join(
rig.homeDir!,
'.gemini',
'tmp',
'background-processes',
);
const logFilePath = path.join(logDir, `background-${pid}.log`);
// Wait for the process to finish and log output
// We'll poll the log file
let logContent = '';
const maxRetries = 40;
let retries = 0;
while (retries < maxRetries) {
if (fs.existsSync(logFilePath)) {
logContent = fs.readFileSync(logFilePath, 'utf8');
if (logContent.includes('end')) {
break;
}
}
await new Promise((resolve) => setTimeout(resolve, 500));
retries++;
}
expect(logContent).toContain('start');
expect(logContent).toContain('end');
// Verify no ANSI escape codes are present (starting with \x1b[ or \u001b[)
const ansiRegex =
// eslint-disable-next-line no-control-regex
/[\u001b\u009b][[()#;?]*(?:[0-9]{1,4}(?:;[0-9]{0,4})*)?[0-9A-ORZcf-nqry=><]/g;
expect(logContent).not.toMatch(ansiRegex);
// Cleanup the log file after test
if (fs.existsSync(logFilePath)) {
fs.unlinkSync(logFilePath);
}
});
});
+2
View File
@@ -103,6 +103,7 @@ import { TerminalProvider } from './ui/contexts/TerminalContext.js';
import { setupTerminalAndTheme } from './utils/terminalTheme.js';
import { profiler } from './ui/components/DebugProfiler.js';
import { runDeferredCommand } from './deferred.js';
import { cleanupBackgroundLogs } from './utils/logCleanup.js';
import { SlashCommandConflictHandler } from './services/SlashCommandConflictHandler.js';
const SLOW_RENDER_MS = 200;
@@ -358,6 +359,7 @@ export async function main() {
await Promise.all([
cleanupCheckpoints(),
cleanupToolOutputFiles(settings.merged),
cleanupBackgroundLogs(),
]);
const parseArgsHandle = startupProfiler.start('parse_arguments');
+5 -3
View File
@@ -428,9 +428,11 @@ export const AppContainer = (props: AppContainerProps) => {
disableMouseEvents();
// Kill all background shells
for (const pid of backgroundShellsRef.current.keys()) {
ShellExecutionService.kill(pid);
}
await Promise.all(
Array.from(backgroundShellsRef.current.keys()).map((pid) =>
ShellExecutionService.kill(pid),
),
);
const ideClient = await IdeClient.getInstance();
await ideClient.disconnect();
@@ -37,6 +37,10 @@ vi.mock('@google/gemini-cli-core', async (importOriginal) => {
ShellExecutionService: {
resizePty: vi.fn(),
subscribe: vi.fn(() => vi.fn()),
getLogFilePath: vi.fn(
(pid) => `~/.gemini/tmp/background-processes/background-${pid}.log`,
),
getLogDir: vi.fn(() => '~/.gemini/tmp/background-processes'),
},
};
});
@@ -221,7 +225,7 @@ describe('<BackgroundShellDisplay />', () => {
expect(ShellExecutionService.resizePty).toHaveBeenCalledWith(
shell1.pid,
76,
21,
20,
);
rerender(
@@ -243,7 +247,7 @@ describe('<BackgroundShellDisplay />', () => {
expect(ShellExecutionService.resizePty).toHaveBeenCalledWith(
shell1.pid,
96,
27,
26,
);
});
@@ -10,6 +10,8 @@ import { useUIActions } from '../contexts/UIActionsContext.js';
import { theme } from '../semantic-colors.js';
import {
ShellExecutionService,
shortenPath,
tildeifyPath,
type AnsiOutput,
type AnsiLine,
type AnsiToken,
@@ -42,8 +44,14 @@ interface BackgroundShellDisplayProps {
const CONTENT_PADDING_X = 1;
const BORDER_WIDTH = 2; // Left and Right border
const HEADER_HEIGHT = 3; // 2 for border, 1 for header
const MAIN_BORDER_HEIGHT = 2; // Top and Bottom border
const HEADER_HEIGHT = 1;
const FOOTER_HEIGHT = 1;
const TOTAL_OVERHEAD_HEIGHT =
MAIN_BORDER_HEIGHT + HEADER_HEIGHT + FOOTER_HEIGHT;
const PROCESS_LIST_HEADER_HEIGHT = 3; // 1 padding top, 1 text, 1 margin bottom
const TAB_DISPLAY_HORIZONTAL_PADDING = 4;
const LOG_PATH_OVERHEAD = 7; // "Log: " (5) + paddingX (2)
const formatShellCommandForDisplay = (command: string, maxWidth: number) => {
const commandFirstLine = command.split('\n')[0];
@@ -79,7 +87,7 @@ export const BackgroundShellDisplay = ({
if (!activePid) return;
const ptyWidth = Math.max(1, width - BORDER_WIDTH - CONTENT_PADDING_X * 2);
const ptyHeight = Math.max(1, height - HEADER_HEIGHT);
const ptyHeight = Math.max(1, height - TOTAL_OVERHEAD_HEIGHT);
ShellExecutionService.resizePty(activePid, ptyWidth, ptyHeight);
}, [activePid, width, height]);
@@ -148,7 +156,7 @@ export const BackgroundShellDisplay = ({
if (keyMatchers[Command.KILL_BACKGROUND_SHELL](key)) {
if (highlightedPid) {
dismissBackgroundShell(highlightedPid);
void dismissBackgroundShell(highlightedPid);
// If we killed the active one, the list might update via props
}
return true;
@@ -169,7 +177,7 @@ export const BackgroundShellDisplay = ({
}
if (keyMatchers[Command.KILL_BACKGROUND_SHELL](key)) {
dismissBackgroundShell(activeShell.pid);
void dismissBackgroundShell(activeShell.pid);
return true;
}
@@ -334,7 +342,10 @@ export const BackgroundShellDisplay = ({
}}
onHighlight={(pid) => setHighlightedPid(pid)}
isFocused={isFocused}
maxItemsToShow={Math.max(1, height - HEADER_HEIGHT - 3)} // Adjust for header
maxItemsToShow={Math.max(
1,
height - TOTAL_OVERHEAD_HEIGHT - PROCESS_LIST_HEADER_HEIGHT,
)}
renderItem={(
item,
{ isSelected: _isSelected, titleColor: _titleColor },
@@ -381,6 +392,23 @@ export const BackgroundShellDisplay = ({
);
};
const renderFooter = () => {
const pidToDisplay = isListOpenProp
? (highlightedPid ?? activePid)
: activePid;
if (!pidToDisplay) return null;
const logPath = ShellExecutionService.getLogFilePath(pidToDisplay);
const displayPath = shortenPath(
tildeifyPath(logPath),
width - LOG_PATH_OVERHEAD,
);
return (
<Box paddingX={1}>
<Text color={theme.text.secondary}>Log: {displayPath}</Text>
</Box>
);
};
const renderOutput = () => {
const lines = typeof output === 'string' ? output.split('\n') : output;
@@ -452,6 +480,7 @@ export const BackgroundShellDisplay = ({
<Box flexGrow={1} overflow="hidden" paddingX={CONTENT_PADDING_X}>
{isListOpenProp ? renderProcessList() : renderOutput()}
</Box>
{renderFooter()}
</Box>
);
};
@@ -60,6 +60,15 @@ const mockSessionStats: SessionStatsState = {
};
describe('<Footer />', () => {
beforeEach(() => {
vi.stubEnv('SANDBOX', '');
vi.stubEnv('SEATBELT_PROFILE', '');
});
afterEach(() => {
vi.unstubAllEnvs();
});
it('renders the component', () => {
const { lastFrame } = renderWithProviders(<Footer />, {
width: 120,
@@ -264,15 +273,6 @@ describe('<Footer />', () => {
});
describe('footer configuration filtering (golden snapshots)', () => {
beforeEach(() => {
vi.stubEnv('SANDBOX', '');
vi.stubEnv('SEATBELT_PROFILE', '');
});
afterEach(() => {
vi.unstubAllEnvs();
});
it('renders complete footer with all sections visible (baseline)', () => {
const { lastFrame } = renderWithProviders(<Footer />, {
width: 120,
@@ -399,6 +399,7 @@ describe('<ModelStatsDisplay />', () => {
const output = lastFrame();
expect(output).toContain('gemini-3-pro-');
expect(output).toContain('gemini-3-flash-');
expect(output).toMatchSnapshot();
});
it('should display role breakdown correctly', () => {
@@ -4,6 +4,7 @@ exports[`<BackgroundShellDisplay /> > highlights the focused state 1`] = `
"┌──────────────────────────────────────────────────────────────────────────────────────────────────┐
│ 1: npm sta... (PID: 1001) (Focused) Close (Ctrl+B) | Kill (Ctrl+K) | List (Ctrl+L) │
│ Starting server... │
│ Log: ~/.gemini/tmp/background-processes/background-1001.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -16,6 +17,7 @@ exports[`<BackgroundShellDisplay /> > keeps exit code status color even when sel
│ 1. npm start (PID: 1001) │
│ 2. tail -f log.txt (PID: 1002) │
│ ● 3. exit 0 (PID: 1003) (Exit Code: 0) │
│ Log: ~/.gemini/tmp/background-processes/background-1003.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -23,6 +25,7 @@ exports[`<BackgroundShellDisplay /> > renders tabs for multiple shells 1`] = `
"┌──────────────────────────────────────────────────────────────────────────────────────────────────┐
│ 1: npm start 2: tail -f lo... (PID: 1001) Close (Ctrl+B) | Kill (Ctrl+K) | List (Ctrl+L) │
│ Starting server... │
│ Log: ~/.gemini/tmp/background-processes/background-1001.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -30,6 +33,7 @@ exports[`<BackgroundShellDisplay /> > renders the output of the active shell 1`]
"┌──────────────────────────────────────────────────────────────────────────────────────────────────┐
│ 1: ... 2: ... (PID: 1001) Close (Ctrl+B) | Kill (Ctrl+K) | List (Ctrl+L) │
│ Starting server... │
│ Log: ~/.gemini/tmp/background-processes/background-1001.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -41,6 +45,7 @@ exports[`<BackgroundShellDisplay /> > renders the process list when isListOpenPr
│ │
│ ● 1. npm start (PID: 1001) │
│ 2. tail -f log.txt (PID: 1002) │
│ Log: ~/.gemini/tmp/background-processes/background-1001.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -52,5 +57,6 @@ exports[`<BackgroundShellDisplay /> > scrolls to active shell when list opens 1`
│ │
│ 1. npm start (PID: 1001) │
│ ● 2. tail -f log.txt (PID: 1002) │
│ Log: ~/.gemini/tmp/background-processes/background-1002.log │
└──────────────────────────────────────────────────────────────────────────────────────────────────┘"
`;
@@ -76,7 +76,7 @@ export interface UIActions {
revealCleanUiDetailsTemporarily: (durationMs?: number) => void;
handleWarning: (message: string) => void;
setEmbeddedShellFocused: (value: boolean) => void;
dismissBackgroundShell: (pid: number) => void;
dismissBackgroundShell: (pid: number) => Promise<void>;
setActiveBackgroundShellPid: (pid: number) => void;
setIsBackgroundShellListOpen: (isOpen: boolean) => void;
setAuthContext: (context: { requiresRestart?: boolean }) => void;
@@ -830,8 +830,8 @@ describe('useShellCommandProcessor', () => {
result.current.registerBackgroundShell(1001, 'bg-cmd', 'initial');
});
act(() => {
result.current.dismissBackgroundShell(1001);
await act(async () => {
await result.current.dismissBackgroundShell(1001);
});
expect(mockShellKill).toHaveBeenCalledWith(1001);
@@ -936,8 +936,8 @@ describe('useShellCommandProcessor', () => {
expect(shell?.exitCode).toBe(1);
// Now dismiss it
act(() => {
result.current.dismissBackgroundShell(999);
await act(async () => {
await result.current.dismissBackgroundShell(999);
});
expect(result.current.backgroundShellCount).toBe(0);
});
@@ -205,11 +205,11 @@ export const useShellCommandProcessor = (
}, [state.activeShellPtyId, activeToolPtyId, m]);
const dismissBackgroundShell = useCallback(
(pid: number) => {
async (pid: number) => {
const shell = state.backgroundShells.get(pid);
if (shell) {
if (shell.status === 'running') {
ShellExecutionService.kill(pid);
await ShellExecutionService.kill(pid);
}
dispatch({ type: 'DISMISS_SHELL', pid });
m.backgroundedPids.delete(pid);
+116
View File
@@ -0,0 +1,116 @@
/**
* @license
* Copyright 2026 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { vi, describe, it, expect, beforeEach } from 'vitest';
import {
promises as fs,
type PathLike,
type Dirent,
type Stats,
} from 'node:fs';
import * as path from 'node:path';
import { cleanupBackgroundLogs } from './logCleanup.js';
vi.mock('@google/gemini-cli-core', () => ({
ShellExecutionService: {
getLogDir: vi.fn().mockReturnValue('/tmp/gemini/tmp/background-processes'),
},
debugLogger: {
debug: vi.fn(),
warn: vi.fn(),
},
}));
vi.mock('node:fs', () => ({
promises: {
access: vi.fn(),
readdir: vi.fn(),
stat: vi.fn(),
unlink: vi.fn(),
},
}));
describe('logCleanup', () => {
const logDir = '/tmp/gemini/tmp/background-processes';
beforeEach(() => {
vi.clearAllMocks();
});
it('should skip cleanup if the directory does not exist', async () => {
vi.mocked(fs.access).mockRejectedValue(new Error('ENOENT'));
await cleanupBackgroundLogs();
expect(fs.access).toHaveBeenCalledWith(logDir);
expect(fs.readdir).not.toHaveBeenCalled();
});
it('should skip cleanup if the directory is empty', async () => {
vi.mocked(fs.access).mockResolvedValue(undefined);
vi.mocked(fs.readdir).mockResolvedValue([]);
await cleanupBackgroundLogs();
expect(fs.readdir).toHaveBeenCalledWith(logDir, { withFileTypes: true });
expect(fs.unlink).not.toHaveBeenCalled();
});
it('should delete log files older than 7 days', async () => {
const now = Date.now();
const oldTime = now - 8 * 24 * 60 * 60 * 1000; // 8 days ago
const newTime = now - 1 * 24 * 60 * 60 * 1000; // 1 day ago
const entries = [
{ name: 'old.log', isFile: () => true },
{ name: 'new.log', isFile: () => true },
{ name: 'not-a-log.txt', isFile: () => true },
{ name: 'some-dir', isFile: () => false },
] as Dirent[];
vi.mocked(fs.access).mockResolvedValue(undefined);
vi.mocked(
fs.readdir as (
path: PathLike,
options: { withFileTypes: true },
) => Promise<Dirent[]>,
).mockResolvedValue(entries);
vi.mocked(fs.stat).mockImplementation((filePath: PathLike) => {
const pathStr = filePath.toString();
if (pathStr.endsWith('old.log')) {
return Promise.resolve({ mtime: new Date(oldTime) } as Stats);
}
if (pathStr.endsWith('new.log')) {
return Promise.resolve({ mtime: new Date(newTime) } as Stats);
}
return Promise.resolve({ mtime: new Date(now) } as Stats);
});
vi.mocked(fs.unlink).mockResolvedValue(undefined);
await cleanupBackgroundLogs();
expect(fs.unlink).toHaveBeenCalledTimes(1);
expect(fs.unlink).toHaveBeenCalledWith(path.join(logDir, 'old.log'));
expect(fs.unlink).not.toHaveBeenCalledWith(path.join(logDir, 'new.log'));
});
it('should handle errors during file deletion gracefully', async () => {
const now = Date.now();
const oldTime = now - 8 * 24 * 60 * 60 * 1000;
const entries = [{ name: 'old.log', isFile: () => true }];
vi.mocked(fs.access).mockResolvedValue(undefined);
// eslint-disable-next-line @typescript-eslint/no-explicit-any
vi.mocked(fs.readdir).mockResolvedValue(entries as any);
// eslint-disable-next-line @typescript-eslint/no-explicit-any
vi.mocked(fs.stat).mockResolvedValue({ mtime: new Date(oldTime) } as any);
vi.mocked(fs.unlink).mockRejectedValue(new Error('Permission denied'));
await expect(cleanupBackgroundLogs()).resolves.not.toThrow();
expect(fs.unlink).toHaveBeenCalled();
});
});
+66
View File
@@ -0,0 +1,66 @@
/**
* @license
* Copyright 2026 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { promises as fs } from 'node:fs';
import * as path from 'node:path';
import { ShellExecutionService, debugLogger } from '@google/gemini-cli-core';
const RETENTION_PERIOD_MS = 7 * 24 * 60 * 60 * 1000; // 7 days
/**
* Cleans up background process log files older than 7 days.
* Scans ~/.gemini/tmp/background-processes/ for .log files.
*
* @param debugMode Whether to log detailed debug information.
*/
export async function cleanupBackgroundLogs(
debugMode: boolean = false,
): Promise<void> {
try {
const logDir = ShellExecutionService.getLogDir();
// Check if the directory exists
try {
await fs.access(logDir);
} catch {
// Directory doesn't exist, nothing to clean up
return;
}
const entries = await fs.readdir(logDir, { withFileTypes: true });
const now = Date.now();
let deletedCount = 0;
for (const entry of entries) {
if (entry.isFile() && entry.name.endsWith('.log')) {
const filePath = path.join(logDir, entry.name);
try {
const stats = await fs.stat(filePath);
if (now - stats.mtime.getTime() > RETENTION_PERIOD_MS) {
await fs.unlink(filePath);
deletedCount++;
}
} catch (error) {
if (debugMode) {
debugLogger.debug(
`Failed to process log file ${entry.name}:`,
error,
);
}
}
}
}
if (deletedCount > 0 && debugMode) {
debugLogger.debug(`Cleaned up ${deletedCount} expired background logs.`);
}
} catch (error) {
// Best-effort cleanup, don't let it crash the CLI
if (debugMode) {
debugLogger.warn('Background log cleanup failed:', error);
}
}
}
@@ -13,6 +13,7 @@ import {
afterEach,
type Mock,
} from 'vitest';
import EventEmitter from 'node:events';
import type { Readable } from 'node:stream';
import { type ChildProcess } from 'node:child_process';
@@ -28,14 +29,44 @@ const mockPtySpawn = vi.hoisted(() => vi.fn());
const mockCpSpawn = vi.hoisted(() => vi.fn());
const mockIsBinary = vi.hoisted(() => vi.fn());
const mockPlatform = vi.hoisted(() => vi.fn());
const mockHomedir = vi.hoisted(() => vi.fn());
const mockMkdirSync = vi.hoisted(() => vi.fn());
const mockCreateWriteStream = vi.hoisted(() => vi.fn());
const mockGetPty = vi.hoisted(() => vi.fn());
const mockSerializeTerminalToObject = vi.hoisted(() => vi.fn());
const mockResolveExecutable = vi.hoisted(() => vi.fn());
const mockDebugLogger = vi.hoisted(() => ({
log: vi.fn(),
warn: vi.fn(),
error: vi.fn(),
debug: vi.fn(),
}));
// Top-level Mocks
vi.mock('../config/storage.js', () => ({
Storage: {
getGlobalTempDir: vi.fn().mockReturnValue('/mock/temp'),
},
}));
vi.mock('../utils/debugLogger.js', () => ({
debugLogger: mockDebugLogger,
}));
vi.mock('@lydell/node-pty', () => ({
spawn: mockPtySpawn,
}));
vi.mock('node:fs', async (importOriginal) => {
const actual = await importOriginal<typeof import('node:fs')>();
return {
...actual,
default: {
...actual,
mkdirSync: mockMkdirSync,
createWriteStream: mockCreateWriteStream,
},
mkdirSync: mockMkdirSync,
createWriteStream: mockCreateWriteStream,
};
});
vi.mock('../utils/shell-utils.js', async (importOriginal) => {
const actual =
await importOriginal<typeof import('../utils/shell-utils.js')>();
@@ -57,6 +88,7 @@ vi.mock('../utils/textUtils.js', () => ({
vi.mock('node:os', () => ({
default: {
platform: mockPlatform,
homedir: mockHomedir,
constants: {
signals: {
SIGTERM: 15,
@@ -65,6 +97,7 @@ vi.mock('node:os', () => ({
},
},
platform: mockPlatform,
homedir: mockHomedir,
constants: {
signals: {
SIGTERM: 15,
@@ -159,6 +192,8 @@ describe('ShellExecutionService', () => {
buffer: {
active: {
viewportY: number;
length: number;
getLine: Mock;
};
};
};
@@ -201,6 +236,8 @@ describe('ShellExecutionService', () => {
buffer: {
active: {
viewportY: 0,
length: 0,
getLine: vi.fn(),
},
},
};
@@ -432,13 +469,21 @@ describe('ShellExecutionService', () => {
});
describe('pty interaction', () => {
let ptySpy: { mockRestore(): void };
beforeEach(() => {
vi.spyOn(ShellExecutionService['activePtys'], 'get').mockReturnValue({
// eslint-disable-next-line @typescript-eslint/no-explicit-any
ptyProcess: mockPtyProcess as any,
// eslint-disable-next-line @typescript-eslint/no-explicit-any
headlessTerminal: mockHeadlessTerminal as any,
});
ptySpy = vi
.spyOn(ShellExecutionService['activePtys'], 'get')
.mockReturnValue({
// eslint-disable-next-line @typescript-eslint/no-explicit-any
ptyProcess: mockPtyProcess as any,
// eslint-disable-next-line @typescript-eslint/no-explicit-any
headlessTerminal: mockHeadlessTerminal as any,
lastSyncedLine: 0,
});
});
afterEach(() => {
ptySpy.mockRestore();
});
it('should write to the pty and trigger a render', async () => {
@@ -667,6 +712,156 @@ describe('ShellExecutionService', () => {
});
});
describe('Backgrounding', () => {
let mockWriteStream: { write: Mock; end: Mock };
let mockBgChildProcess: EventEmitter & Partial<ChildProcess>;
beforeEach(async () => {
mockWriteStream = {
write: vi.fn(),
end: vi.fn().mockImplementation((cb) => cb?.()),
};
mockMkdirSync.mockReturnValue(undefined);
mockCreateWriteStream.mockReturnValue(
// eslint-disable-next-line @typescript-eslint/no-explicit-any
mockWriteStream as any,
);
mockHomedir.mockReturnValue('/mock/home');
mockBgChildProcess = new EventEmitter() as EventEmitter &
Partial<ChildProcess>;
mockBgChildProcess.stdout = new EventEmitter() as Readable;
mockBgChildProcess.stderr = new EventEmitter() as Readable;
mockBgChildProcess.kill = vi.fn();
Object.defineProperty(mockBgChildProcess, 'pid', {
value: 99999,
configurable: true,
});
mockCpSpawn.mockReturnValue(mockBgChildProcess);
// Explicitly clear state between runs
// eslint-disable-next-line @typescript-eslint/no-explicit-any
(ShellExecutionService as any).backgroundLogStreams.clear();
// eslint-disable-next-line @typescript-eslint/no-explicit-any
(ShellExecutionService as any).activePtys.clear();
// eslint-disable-next-line @typescript-eslint/no-explicit-any
(ShellExecutionService as any).activeChildProcesses.clear();
});
afterEach(() => {
// eslint-disable-next-line @typescript-eslint/no-explicit-any
(ShellExecutionService as any).backgroundLogStreams.clear();
});
it('should move a running pty process to the background and start logging', async () => {
const abortController = new AbortController();
const handle = await ShellExecutionService.execute(
'long-running-pty',
'/',
onOutputEventMock,
abortController.signal,
true,
shellExecutionConfig,
);
// Use the registered onData listener
const onDataListener = mockPtyProcess.onData.mock.calls[0][0];
onDataListener('initial pty output');
// Wait for async write to headless terminal
await new Promise((resolve) => setTimeout(resolve, 100));
mockSerializeTerminalToObject.mockReturnValue([
[{ text: 'initial pty output', fg: '', bg: '' }],
]);
// Background the process
ShellExecutionService.background(handle.pid!);
const result = await handle.result;
expect(result.backgrounded).toBe(true);
expect(result.output).toContain('initial pty output');
expect(mockMkdirSync).toHaveBeenCalledWith(
expect.stringContaining('background-processes'),
{ recursive: true },
);
// Verify initial output was written
expect(mockWriteStream.write).toHaveBeenCalledWith(
expect.stringContaining('initial pty output'),
);
await ShellExecutionService.kill(handle.pid!);
expect(mockWriteStream.end).toHaveBeenCalled();
});
it('should continue logging after backgrounding for child_process', async () => {
mockGetPty.mockResolvedValue(null); // Force child_process fallback
const abortController = new AbortController();
const handle = await ShellExecutionService.execute(
'long-running-cp',
'/',
onOutputEventMock,
abortController.signal,
true,
shellExecutionConfig,
);
// Trigger data before backgrounding
mockBgChildProcess.stdout?.emit('data', Buffer.from('initial cp output'));
await new Promise((resolve) => process.nextTick(resolve));
ShellExecutionService.background(handle.pid!);
const result = await handle.result;
expect(result.backgrounded).toBe(true);
expect(result.output).toBe('initial cp output');
expect(mockWriteStream.write).toHaveBeenCalledWith('initial cp output\n');
// Subsequent output
mockBgChildProcess.stdout?.emit('data', Buffer.from('more cp output'));
await new Promise((resolve) => process.nextTick(resolve));
expect(mockWriteStream.write).toHaveBeenCalledWith('more cp output');
await ShellExecutionService.kill(handle.pid!);
expect(mockWriteStream.end).toHaveBeenCalled();
});
it('should log a warning if background log setup fails', async () => {
const abortController = new AbortController();
const handle = await ShellExecutionService.execute(
'failing-log-setup',
'/',
onOutputEventMock,
abortController.signal,
true,
shellExecutionConfig,
);
// Mock mkdirSync to fail
const error = new Error('Permission denied');
mockMkdirSync.mockImplementationOnce(() => {
throw error;
});
// Background the process
ShellExecutionService.background(handle.pid!);
const result = await handle.result;
expect(result.backgrounded).toBe(true);
expect(mockDebugLogger.warn).toHaveBeenCalledWith(
'Failed to setup background logging:',
error,
);
await ShellExecutionService.kill(handle.pid!);
});
});
describe('Binary Output', () => {
it('should detect binary output and switch to progress events', async () => {
mockIsBinary.mockReturnValueOnce(true);
@@ -10,6 +10,8 @@ import { getPty } from '../utils/getPty.js';
import { spawn as cpSpawn, type ChildProcess } from 'node:child_process';
import { TextDecoder } from 'node:util';
import os from 'node:os';
import fs, { mkdirSync } from 'node:fs';
import path from 'node:path';
import type { IPty } from '@lydell/node-pty';
import { getCachedEncodingForBuffer } from '../utils/systemEncoding.js';
import {
@@ -19,6 +21,8 @@ import {
} from '../utils/shell-utils.js';
import { isBinary } from '../utils/textUtils.js';
import pkg from '@xterm/headless';
import { debugLogger } from '../utils/debugLogger.js';
import { Storage } from '../config/storage.js';
import {
serializeTerminalToObject,
type AnsiOutput,
@@ -142,6 +146,7 @@ interface ActivePty {
ptyProcess: IPty;
headlessTerminal: pkg.Terminal;
maxSerializedLines?: number;
lastSyncedLine: number;
}
interface ActiveChildProcess {
@@ -150,23 +155,41 @@ interface ActiveChildProcess {
output: string;
truncated: boolean;
outputChunks: Buffer[];
lastSyncedOffset: number;
};
}
const getFullBufferText = (terminal: pkg.Terminal): string => {
const findLastContentLine = (
buffer: pkg.IBuffer,
startLine: number,
): number => {
const lineCount = buffer.length;
for (let i = lineCount - 1; i >= startLine; i--) {
const line = buffer.getLine(i);
if (line && line.translateToString(true).length > 0) {
return i;
}
}
return -1;
};
const getFullBufferText = (terminal: pkg.Terminal, startLine = 0): string => {
const buffer = terminal.buffer.active;
const lines: string[] = [];
for (let i = 0; i < buffer.length; i++) {
const lastContentLine = findLastContentLine(buffer, startLine);
if (lastContentLine === -1 || lastContentLine < startLine) return '';
for (let i = startLine; i <= lastContentLine; i++) {
const line = buffer.getLine(i);
if (!line) {
lines.push('');
continue;
}
// If the NEXT line is wrapped, it means it's a continuation of THIS line.
// We should not trim the right side of this line because trailing spaces
// might be significant parts of the wrapped content.
// If it's not wrapped, we trim normally.
let trimRight = true;
if (i + 1 < buffer.length) {
if (i + 1 <= lastContentLine) {
const nextLine = buffer.getLine(i + 1);
if (nextLine?.isWrapped) {
trimRight = false;
@@ -182,12 +205,53 @@ const getFullBufferText = (terminal: pkg.Terminal): string => {
}
}
// Remove trailing empty lines
while (lines.length > 0 && lines[lines.length - 1] === '') {
lines.pop();
return lines.join('\n');
};
const writeBufferToLogStream = (
terminal: pkg.Terminal,
stream: fs.WriteStream,
startLine = 0,
): number => {
const buffer = terminal.buffer.active;
const lastContentLine = findLastContentLine(buffer, startLine);
if (lastContentLine === -1 || lastContentLine < startLine) return startLine;
for (let i = startLine; i <= lastContentLine; i++) {
const line = buffer.getLine(i);
if (!line) {
stream.write('\n');
continue;
}
let trimRight = true;
if (i + 1 <= lastContentLine) {
const nextLine = buffer.getLine(i + 1);
if (nextLine?.isWrapped) {
trimRight = false;
}
}
const lineContent = line.translateToString(trimRight);
const stripped = stripAnsi(lineContent);
if (line.isWrapped) {
stream.write(stripped);
} else {
if (i > startLine) {
stream.write('\n');
}
stream.write(stripped);
}
}
return lines.join('\n');
// Ensure it ends with a newline if we wrote anything
if (lastContentLine >= startLine) {
stream.write('\n');
}
return lastContentLine + 1;
};
/**
@@ -199,10 +263,43 @@ const getFullBufferText = (terminal: pkg.Terminal): string => {
export class ShellExecutionService {
private static activePtys = new Map<number, ActivePty>();
private static activeChildProcesses = new Map<number, ActiveChildProcess>();
private static backgroundLogPids = new Set<number>();
private static backgroundLogStreams = new Map<number, fs.WriteStream>();
private static exitedPtyInfo = new Map<
number,
{ exitCode: number; signal?: number }
>();
static getLogDir(): string {
return path.join(Storage.getGlobalTempDir(), 'background-processes');
}
static getLogFilePath(pid: number): string {
return path.join(this.getLogDir(), `background-${pid}.log`);
}
private static syncBackgroundLog(pid: number, content: string): void {
if (!this.backgroundLogPids.has(pid)) return;
const stream = this.backgroundLogStreams.get(pid);
if (stream && content) {
// Strip ANSI escape codes before logging
stream.write(stripAnsi(content));
}
}
private static async cleanupLogStream(pid: number): Promise<void> {
const stream = this.backgroundLogStreams.get(pid);
if (stream) {
await new Promise<void>((resolve) => {
stream.end(() => resolve());
});
this.backgroundLogStreams.delete(pid);
}
this.backgroundLogPids.delete(pid);
}
private static activeResolvers = new Map<
number,
(res: ShellExecutionResult) => void
@@ -326,6 +423,7 @@ export class ShellExecutionService {
output: '',
truncated: false,
outputChunks: [] as Buffer[],
lastSyncedOffset: 0,
};
if (child.pid) {
@@ -395,7 +493,23 @@ export class ShellExecutionService {
chunk: decodedChunk,
};
onOutputEvent(event);
if (child.pid) ShellExecutionService.emitEvent(child.pid, event);
if (child.pid) {
ShellExecutionService.emitEvent(child.pid, event);
if (ShellExecutionService.backgroundLogPids.has(child.pid)) {
const activeChild =
ShellExecutionService.activeChildProcesses.get(child.pid);
if (activeChild) {
const delta = activeChild.state.output.substring(
activeChild.state.lastSyncedOffset,
);
if (delta) {
ShellExecutionService.syncBackgroundLog(child.pid, delta);
activeChild.state.lastSyncedOffset =
activeChild.state.output.length;
}
}
}
}
}
} else {
const totalBytes = state.outputChunks.reduce(
@@ -431,17 +545,21 @@ export class ShellExecutionService {
const exitSignal = signal ? os.constants.signals[signal] : null;
if (child.pid) {
const pid = child.pid;
const event: ShellOutputEvent = {
type: 'exit',
exitCode,
signal: exitSignal,
};
onOutputEvent(event);
ShellExecutionService.emitEvent(child.pid, event);
ShellExecutionService.emitEvent(pid, event);
this.activeChildProcesses.delete(child.pid);
this.activeResolvers.delete(child.pid);
this.activeListeners.delete(child.pid);
// eslint-disable-next-line @typescript-eslint/no-floating-promises
ShellExecutionService.cleanupLogStream(pid).then(() => {
this.activeChildProcesses.delete(pid);
this.activeResolvers.delete(pid);
this.activeListeners.delete(pid);
});
}
resolve({
@@ -601,6 +719,7 @@ export class ShellExecutionService {
ptyProcess,
headlessTerminal,
maxSerializedLines: shellExecutionConfig.maxSerializedLines,
lastSyncedLine: 0,
});
let processingChain = Promise.resolve();
@@ -696,6 +815,26 @@ export class ShellExecutionService {
};
onOutputEvent(event);
ShellExecutionService.emitEvent(ptyProcess.pid, event);
if (ShellExecutionService.backgroundLogPids.has(ptyProcess.pid)) {
const activePty = ShellExecutionService.activePtys.get(
ptyProcess.pid,
);
const stream = ShellExecutionService.backgroundLogStreams.get(
ptyProcess.pid,
);
if (activePty && stream) {
const terminal = activePty.headlessTerminal;
const currentLine = terminal.buffer.active.length;
if (currentLine > activePty.lastSyncedLine) {
activePty.lastSyncedLine = writeBufferToLogStream(
terminal,
stream,
activePty.lastSyncedLine,
);
}
}
}
}
};
@@ -789,7 +928,6 @@ export class ShellExecutionService {
({ exitCode, signal }: { exitCode: number; signal?: number }) => {
exited = true;
abortSignal.removeEventListener('abort', abortHandler);
this.activePtys.delete(ptyProcess.pid);
// Attempt to destroy the PTY to ensure FD is closed
try {
// eslint-disable-next-line @typescript-eslint/no-unsafe-type-assertion
@@ -810,30 +948,35 @@ export class ShellExecutionService {
5 * 60 * 1000,
).unref();
this.activePtys.delete(ptyProcess.pid);
this.activeResolvers.delete(ptyProcess.pid);
// eslint-disable-next-line @typescript-eslint/no-floating-promises
ShellExecutionService.cleanupLogStream(ptyProcess.pid).then(
() => {
this.activePtys.delete(ptyProcess.pid);
this.activeResolvers.delete(ptyProcess.pid);
const event: ShellOutputEvent = {
type: 'exit',
exitCode,
signal: signal ?? null,
};
onOutputEvent(event);
ShellExecutionService.emitEvent(ptyProcess.pid, event);
this.activeListeners.delete(ptyProcess.pid);
const event: ShellOutputEvent = {
type: 'exit',
exitCode,
signal: signal ?? null,
};
onOutputEvent(event);
ShellExecutionService.emitEvent(ptyProcess.pid, event);
this.activeListeners.delete(ptyProcess.pid);
const finalBuffer = Buffer.concat(outputChunks);
const finalBuffer = Buffer.concat(outputChunks);
resolve({
rawOutput: finalBuffer,
output: getFullBufferText(headlessTerminal),
exitCode,
signal: signal ?? null,
error,
aborted: abortSignal.aborted,
pid: ptyProcess.pid,
executionMethod: ptyInfo?.name ?? 'node-pty',
});
resolve({
rawOutput: finalBuffer,
output: getFullBufferText(headlessTerminal),
exitCode,
signal: signal ?? null,
error,
aborted: abortSignal.aborted,
pid: ptyProcess.pid,
executionMethod: ptyInfo?.name ?? 'node-pty',
});
},
);
};
if (abortSignal.aborted) {
@@ -994,10 +1137,12 @@ export class ShellExecutionService {
*
* @param pid The process ID to kill.
*/
static kill(pid: number): void {
static async kill(pid: number): Promise<void> {
const activePty = this.activePtys.get(pid);
const activeChild = this.activeChildProcesses.get(pid);
await this.cleanupLogStream(pid);
if (activeChild) {
killProcessGroup({ pid }).catch(() => {});
this.activeChildProcesses.delete(pid);
@@ -1018,44 +1163,55 @@ export class ShellExecutionService {
*/
static background(pid: number): void {
const resolve = this.activeResolvers.get(pid);
if (resolve) {
let output = '';
const rawOutput = Buffer.from('');
if (!resolve) return;
const activePty = this.activePtys.get(pid);
const activeChild = this.activeChildProcesses.get(pid);
const activePty = this.activePtys.get(pid);
const activeChild = this.activeChildProcesses.get(pid);
if (!activePty && !activeChild) return;
const output = activePty
? getFullBufferText(activePty.headlessTerminal)
: (activeChild?.state.output ?? '');
const executionMethod = activePty ? 'node-pty' : 'child_process';
this.backgroundLogPids.add(pid);
const logPath = this.getLogFilePath(pid);
const logDir = this.getLogDir();
try {
mkdirSync(logDir, { recursive: true });
const stream = fs.createWriteStream(logPath, { flags: 'w' });
this.backgroundLogStreams.set(pid, stream);
if (activePty) {
output = getFullBufferText(activePty.headlessTerminal);
resolve({
rawOutput,
output,
exitCode: null,
signal: null,
error: null,
aborted: false,
pid,
executionMethod: 'node-pty',
backgrounded: true,
});
activePty.lastSyncedLine = writeBufferToLogStream(
activePty.headlessTerminal,
stream,
0,
);
} else if (activeChild) {
output = activeChild.state.output;
resolve({
rawOutput,
output,
exitCode: null,
signal: null,
error: null,
aborted: false,
pid,
executionMethod: 'child_process',
backgrounded: true,
});
if (output) {
stream.write(stripAnsi(output) + '\n');
}
activeChild.state.lastSyncedOffset = activeChild.state.output.length;
}
this.activeResolvers.delete(pid);
} catch (e) {
debugLogger.warn('Failed to setup background logging:', e);
}
resolve({
rawOutput: Buffer.from(''),
output,
exitCode: null,
signal: null,
error: null,
aborted: false,
pid,
executionMethod,
backgrounded: true,
});
this.activeResolvers.delete(pid);
}
static subscribe(