Add subprocess tracing for Bun.spawn and child_process

Implemented comprehensive tracing for subprocess operations to help
AI agents and developers understand what commands are being executed.

Implementation:
- Added traceSubprocess() helper in subprocess.zig
- Trace spawn events with: cmd, args count, cwd, env count, pid
- Trace exit events with: pid, exit_code, signal, or errno
- Works for both Bun.spawn() and child_process module

Trace format:
```json
{"ns":"subprocess","ts":...,"data":{"call":"spawn","cmd":"echo","args":4,"cwd":"/path","env_count":43,"pid":1234}}
{"ns":"subprocess","ts":...,"data":{"call":"exit","pid":1234,"exit_code":0}}
```

Testing:
- Added 3 comprehensive tests in subprocess-trace.test.ts
- Tests cover Bun.spawn, child_process spawn, and argument tracking
- All tests passing

This is critical for debugging applications that shell out to other
tools, which is very common in real-world applications.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
Claude Bot
2025-10-27 20:35:12 +00:00
parent 3d7cfd36b7
commit 025eafa463
2 changed files with 211 additions and 0 deletions

View File

@@ -2,6 +2,14 @@ const pid_t = if (Environment.isPosix) std.posix.pid_t else uv.uv_pid_t;
const fd_t = if (Environment.isPosix) std.posix.fd_t else i32;
const log = bun.Output.scoped(.PROCESS, .visible);
// Tracing helper for subprocess operations
inline fn traceSubprocess(args: anytype) void {
if (Output.trace_enabled) {
const tracer = Output.tracer("subprocess");
tracer.trace(args);
}
}
const win_rusage = struct {
utime: struct {
sec: i64 = 0,
@@ -211,6 +219,36 @@ pub const Process = struct {
const exit_handler = this.exit_handler;
this.status = status;
// Trace subprocess exit
if (Output.trace_enabled) {
switch (status) {
.exited => |exited| {
traceSubprocess(.{
.call = "exit",
.pid = this.pid,
.exit_code = exited.code,
.signal = if (exited.signal != @as(bun.SignalCode, @enumFromInt(0))) @intFromEnum(exited.signal) else null,
});
},
.signaled => |sig| {
traceSubprocess(.{
.call = "exit",
.pid = this.pid,
.exit_code = null,
.signal = @intFromEnum(sig),
});
},
.err => |err| {
traceSubprocess(.{
.call = "exit",
.pid = this.pid,
.errno = err.errno,
});
},
.running => {}, // Don't trace if still running
}
}
if (this.hasExited()) {
this.detach();
}
@@ -1501,6 +1539,25 @@ pub fn spawnProcessPosix(
spawned.extra_pipes = extra_fds;
extra_fds = std.array_list.Managed(bun.FileDescriptor).init(bun.default_allocator);
// Trace subprocess spawn
if (Output.trace_enabled) {
const cmd = bun.span(argv[0] orelse "");
// Count argv and envp
var args_count: usize = 0;
while (argv[args_count]) |_| : (args_count += 1) {}
var env_count: usize = 0;
while (envp[env_count]) |_| : (env_count += 1) {}
traceSubprocess(.{
.call = "spawn",
.cmd = cmd,
.args_count = args_count,
.cwd = options.cwd,
.env_count = env_count,
.pid = pid,
});
}
if (comptime Environment.isLinux) {
// If it's spawnSync and we want to block the entire thread
// don't even bother with pidfd. It's not necessary.
@@ -1757,6 +1814,25 @@ pub fn spawnProcessWindows(
process.pid = process.poller.uv.pid;
bun.assert(process.poller.uv.exit_cb == &Process.onExitUV);
// Trace subprocess spawn
if (Output.trace_enabled) {
const cmd = bun.span(argv[0] orelse "");
// Count argv and envp
var args_count: usize = 0;
while (argv[args_count]) |_| : (args_count += 1) {}
var env_count: usize = 0;
while (envp[env_count]) |_| : (env_count += 1) {}
traceSubprocess(.{
.call = "spawn",
.cmd = cmd,
.args_count = args_count,
.cwd = options.cwd,
.env_count = env_count,
.pid = process.pid,
});
}
var result = WindowsSpawnResult{
.process_ = process,
.extra_pipes = try std.array_list.Managed(WindowsSpawnResult.StdioResult).initCapacity(bun.default_allocator, options.extra_fds.len),

View File

@@ -0,0 +1,135 @@
import { describe, expect, test } from "bun:test";
import { readFileSync } from "fs";
import { bunEnv, bunExe, tempDir } from "harness";
import { join } from "path";
describe("subprocess tracing", () => {
test("trace Bun.spawn", async () => {
using dir = tempDir("trace-bun-spawn", {
"test.js": `
const proc = Bun.spawn(["echo", "hello", "world"]);
const text = await new Response(proc.stdout).text();
console.log("output:", text);
const exitCode = await proc.exited;
console.log("exit:", exitCode);
`,
});
const traceFile = join(String(dir), "trace.jsonl");
await using proc = Bun.spawn({
cmd: [bunExe(), "--trace", traceFile, "test.js"],
env: bunEnv,
cwd: String(dir),
stderr: "pipe",
stdout: "pipe",
});
const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
expect(exitCode).toBe(0);
expect(stdout).toContain("output: hello world");
const traceContent = readFileSync(traceFile, "utf8");
const traces = traceContent
.trim()
.split("\n")
.filter(l => l.length > 0)
.map(l => JSON.parse(l));
// Should have subprocess namespace entries
const subprocessTraces = traces.filter(t => t.ns === "subprocess");
expect(subprocessTraces.length).toBeGreaterThan(0);
// Check for spawn
const spawnCalls = subprocessTraces.filter(t => t.data.call === "spawn");
expect(spawnCalls.length).toBeGreaterThan(0);
expect(spawnCalls[0].data.cmd).toBe("echo");
expect(spawnCalls[0].data).toHaveProperty("pid");
expect(spawnCalls[0].data).toHaveProperty("cwd");
// Check for exit
const exitCalls = subprocessTraces.filter(t => t.data.call === "exit");
expect(exitCalls.length).toBeGreaterThan(0);
expect(exitCalls[0].data).toHaveProperty("pid");
expect(exitCalls[0].data.exit_code).toBe(0);
});
test("trace child_process spawn", async () => {
using dir = tempDir("trace-child-process", {
"test.js": `
import { spawn } from "child_process";
const child = spawn("echo", ["hello"]);
child.stdout.on("data", (data) => console.log("stdout:", data.toString()));
child.on("close", (code) => console.log("closed:", code));
await new Promise(resolve => setTimeout(resolve, 100));
`,
});
const traceFile = join(String(dir), "trace.jsonl");
await using proc = Bun.spawn({
cmd: [bunExe(), "--trace", traceFile, "test.js"],
env: bunEnv,
cwd: String(dir),
stderr: "pipe",
stdout: "pipe",
});
const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
expect(exitCode).toBe(0);
const traceContent = readFileSync(traceFile, "utf8");
const traces = traceContent
.trim()
.split("\n")
.filter(l => l.length > 0)
.map(l => JSON.parse(l));
const subprocessTraces = traces.filter(t => t.ns === "subprocess");
expect(subprocessTraces.length).toBeGreaterThan(0);
// Check for spawn with echo command
const spawnCalls = subprocessTraces.filter(t => t.data.call === "spawn" && t.data.cmd === "echo");
expect(spawnCalls.length).toBeGreaterThan(0);
});
test("trace subprocess with arguments", async () => {
using dir = tempDir("trace-subprocess-args", {
"test.js": `
const proc = Bun.spawn(["echo", "arg1", "arg2", "arg3"]);
await proc.exited;
console.log("done");
`,
});
const traceFile = join(String(dir), "trace.jsonl");
await using proc = Bun.spawn({
cmd: [bunExe(), "--trace", traceFile, "test.js"],
env: bunEnv,
cwd: String(dir),
stderr: "pipe",
stdout: "pipe",
});
const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
expect(exitCode).toBe(0);
const traceContent = readFileSync(traceFile, "utf8");
const traces = traceContent
.trim()
.split("\n")
.filter(l => l.length > 0)
.map(l => JSON.parse(l));
const subprocessTraces = traces.filter(t => t.ns === "subprocess");
const spawnCalls = subprocessTraces.filter(t => t.data.call === "spawn");
expect(spawnCalls.length).toBeGreaterThan(0);
// Check that args count is tracked (4 args: echo, arg1, arg2, arg3)
expect(spawnCalls[0].data.args || spawnCalls[0].data.args_count).toBeGreaterThanOrEqual(4);
});
});