diff --git a/src/Watcher.zig b/src/Watcher.zig index c62a9aab0f..5cb78f9244 100644 --- a/src/Watcher.zig +++ b/src/Watcher.zig @@ -4,6 +4,7 @@ const Watcher = @This(); const DebugLogScope = bun.Output.Scoped(.watcher, .visible); const log = DebugLogScope.log; +const WatcherTrace = @import("./watcher/WatcherTrace.zig"); // This will always be [max_count]WatchEvent, // We avoid statically allocating because it increases the binary size. @@ -95,9 +96,18 @@ pub fn init(comptime T: type, ctx: *T, fs: *bun.fs.FileSystem, allocator: std.me try Platform.init(&watcher.platform, fs.top_level_dir); + // Initialize trace file if BUN_WATCHER_TRACE env var is set + WatcherTrace.init(); + return watcher; } +/// Write trace events to the trace file if enabled. +/// This runs on the watcher thread, so no locking is needed. +pub fn writeTraceEvents(this: *Watcher, events: []WatchEvent, changed_files: []?[:0]u8) void { + WatcherTrace.writeEvents(this, events, changed_files); +} + pub fn start(this: *Watcher) !void { bun.assert(this.watchloop_handle == null); this.thread = try std.Thread.spawn(.{}, threadMain, .{this}); @@ -244,6 +254,9 @@ fn threadMain(this: *Watcher) !void { } this.watchlist.deinit(this.allocator); + // Close trace file if open + WatcherTrace.deinit(); + const allocator = this.allocator; allocator.destroy(this); } diff --git a/src/watcher/INotifyWatcher.zig b/src/watcher/INotifyWatcher.zig index d468d4f30b..b4996fa5b2 100644 --- a/src/watcher/INotifyWatcher.zig +++ b/src/watcher/INotifyWatcher.zig @@ -352,6 +352,7 @@ fn processINotifyEventBatch(this: *bun.Watcher, event_count: usize, temp_name_li defer this.mutex.unlock(); if (this.running) { // all_events.len == 0 is checked above, so last_event_index + 1 is safe + this.writeTraceEvents(all_events[0 .. last_event_index + 1], this.changed_filepaths[0..name_off]); this.onFileUpdate(this.ctx, all_events[0 .. last_event_index + 1], this.changed_filepaths[0..name_off], this.watchlist); } diff --git a/src/watcher/KEventWatcher.zig b/src/watcher/KEventWatcher.zig index 7886e265aa..c8ac49087d 100644 --- a/src/watcher/KEventWatcher.zig +++ b/src/watcher/KEventWatcher.zig @@ -93,6 +93,7 @@ pub fn watchLoopCycle(this: *Watcher) bun.sys.Maybe(void) { this.mutex.lock(); defer this.mutex.unlock(); if (this.running) { + this.writeTraceEvents(watchevents, this.changed_filepaths[0..watchevents.len]); this.onFileUpdate(this.ctx, watchevents, this.changed_filepaths[0..watchevents.len], this.watchlist); } diff --git a/src/watcher/WatcherTrace.zig b/src/watcher/WatcherTrace.zig new file mode 100644 index 0000000000..68d66076fb --- /dev/null +++ b/src/watcher/WatcherTrace.zig @@ -0,0 +1,108 @@ +const std = @import("std"); +const bun = @import("../bun.zig"); +const Watcher = @import("../Watcher.zig"); + +/// Optional trace file for debugging watcher events +var trace_file: ?bun.FileDescriptor = null; + +/// Initialize trace file if BUN_WATCHER_TRACE env var is set. +/// Only checks once on first call. +pub fn init() void { + if (trace_file != null) return; + + if (bun.getenvZ("BUN_WATCHER_TRACE")) |trace_path| { + if (trace_path.len > 0) { + const flags = bun.O.WRONLY | bun.O.CREAT | bun.O.APPEND; + const mode = 0o644; + switch (bun.sys.openA(trace_path, flags, mode)) { + .result => |fd| { + trace_file = fd; + }, + .err => { + // Silently ignore errors opening trace file + }, + } + } + } +} + +/// Write trace events to the trace file if enabled. +/// This is called from the watcher thread, so no locking is needed. +pub fn writeEvents(watcher: *Watcher, events: []Watcher.WatchEvent, changed_files: []?[:0]u8) void { + const fd = trace_file orelse return; + + var buf: [16384]u8 = undefined; + var stream = std.io.fixedBufferStream(&buf); + const writer = stream.writer(); + + // Get current timestamp + const timestamp = std.time.milliTimestamp(); + + for (events) |event| { + stream.reset(); + + const watchlist_slice = watcher.watchlist.slice(); + const file_paths = watchlist_slice.items(.file_path); + const file_path = if (event.index < file_paths.len) file_paths[event.index] else "(unknown)"; + + // Write JSON manually for each event + writer.writeAll("{\"timestamp\":") catch return; + writer.print("{d}", .{timestamp}) catch return; + writer.writeAll(",\"index\":") catch return; + writer.print("{d}", .{event.index}) catch return; + writer.writeAll(",\"path\":\"") catch return; + + // Escape quotes and backslashes in path + for (file_path) |c| { + if (c == '"' or c == '\\') { + writer.writeByte('\\') catch return; + } + writer.writeByte(c) catch return; + } + writer.writeAll("\"") catch return; + + // Write individual operation flags + writer.writeAll(",\"delete\":") catch return; + writer.writeAll(if (event.op.delete) "true" else "false") catch return; + writer.writeAll(",\"write\":") catch return; + writer.writeAll(if (event.op.write) "true" else "false") catch return; + writer.writeAll(",\"rename\":") catch return; + writer.writeAll(if (event.op.rename) "true" else "false") catch return; + writer.writeAll(",\"metadata\":") catch return; + writer.writeAll(if (event.op.metadata) "true" else "false") catch return; + writer.writeAll(",\"move_to\":") catch return; + writer.writeAll(if (event.op.move_to) "true" else "false") catch return; + + // Add changed file names if any + const names = event.names(changed_files); + writer.writeAll(",\"changed_files\":[") catch return; + var first = true; + for (names) |name_opt| { + if (name_opt) |name| { + if (!first) writer.writeAll(",") catch return; + first = false; + writer.writeAll("\"") catch return; + // Escape quotes and backslashes in filename + for (name) |c| { + if (c == '"' or c == '\\') { + writer.writeByte('\\') catch return; + } + writer.writeByte(c) catch return; + } + writer.writeAll("\"") catch return; + } + } + writer.writeAll("]}\n") catch return; + + const written = stream.getWritten(); + _ = bun.sys.write(fd, written); + } +} + +/// Close the trace file if open +pub fn deinit() void { + if (trace_file) |fd| { + fd.close(); + trace_file = null; + } +} diff --git a/src/watcher/WindowsWatcher.zig b/src/watcher/WindowsWatcher.zig index a2b8459c38..e1319389a1 100644 --- a/src/watcher/WindowsWatcher.zig +++ b/src/watcher/WindowsWatcher.zig @@ -293,6 +293,7 @@ fn processWatchEventBatch(this: *bun.Watcher, event_count: usize) bun.sys.Maybe( log("calling onFileUpdate (all_events.len = {d})", .{all_events.len}); + this.writeTraceEvents(all_events, this.changed_filepaths[0 .. last_event_index + 1]); this.onFileUpdate(this.ctx, all_events, this.changed_filepaths[0 .. last_event_index + 1], this.watchlist); return .success; diff --git a/test/cli/watch/watcher-trace.test.ts b/test/cli/watch/watcher-trace.test.ts new file mode 100644 index 0000000000..e324734440 --- /dev/null +++ b/test/cli/watch/watcher-trace.test.ts @@ -0,0 +1,281 @@ +import { expect, test } from "bun:test"; +import { bunEnv, bunExe, tempDir } from "harness"; +import { existsSync, readFileSync } from "node:fs"; +import { join } from "node:path"; + +test("BUN_WATCHER_TRACE creates trace file with watch events", async () => { + using dir = tempDir("watcher-trace", { + "index.js": `console.log("hello");`, + "watcher.js": ` + import { watch } from "fs"; + const watcher = watch(".", { recursive: true }, (eventType, filename) => { + console.log("WATCHER_EVENT", eventType, filename); + }); + // Keep the process alive for a bit + setTimeout(() => { + watcher.close(); + process.exit(0); + }, 3000); + `, + }); + + const traceFile = join(String(dir), "trace.log"); + const env = { ...bunEnv, BUN_WATCHER_TRACE: traceFile }; + + await using proc = Bun.spawn({ + cmd: [bunExe(), "watcher.js"], + env, + cwd: String(dir), + stdout: "pipe", + stderr: "pipe", + }); + + // Give watcher time to initialize + await Bun.sleep(500); + + // Write to a file to trigger a watch event + await Bun.write(join(String(dir), "test.txt"), "test content"); + await Bun.sleep(500); + + // Modify the file + await Bun.write(join(String(dir), "test.txt"), "modified content"); + await Bun.sleep(500); + + // Delete the file + await Bun.write(join(String(dir), "delete.txt"), "to be deleted"); + await Bun.sleep(300); + await Bun.$`rm ${join(String(dir), "delete.txt")}`.quiet(); + await Bun.sleep(500); + + const exitCode = await proc.exited; + + // Check that trace file was created + expect(existsSync(traceFile)).toBe(true); + + const traceContent = readFileSync(traceFile, "utf-8"); + const lines = traceContent.trim().split("\n"); + + // Should have at least one event + expect(lines.length).toBeGreaterThan(0); + + // Parse and validate JSON structure + for (const line of lines) { + if (line.trim()) { + const event = JSON.parse(line); + + // Check required fields exist + expect(event).toHaveProperty("timestamp"); + expect(event).toHaveProperty("index"); + expect(event).toHaveProperty("path"); + expect(event).toHaveProperty("delete"); + expect(event).toHaveProperty("write"); + expect(event).toHaveProperty("rename"); + expect(event).toHaveProperty("metadata"); + expect(event).toHaveProperty("move_to"); + expect(event).toHaveProperty("changed_files"); + + // Validate types + expect(typeof event.timestamp).toBe("number"); + expect(typeof event.index).toBe("number"); + expect(typeof event.path).toBe("string"); + expect(typeof event.delete).toBe("boolean"); + expect(typeof event.write).toBe("boolean"); + expect(typeof event.rename).toBe("boolean"); + expect(typeof event.metadata).toBe("boolean"); + expect(typeof event.move_to).toBe("boolean"); + expect(Array.isArray(event.changed_files)).toBe(true); + } + } +}, 10000); + +test("BUN_WATCHER_TRACE with --watch flag", async () => { + using dir = tempDir("watcher-trace-watch", { + "script.js": `console.log("run", 0);`, + }); + + const traceFile = join(String(dir), "watch-trace.log"); + const env = { ...bunEnv, BUN_WATCHER_TRACE: traceFile }; + + const proc = Bun.spawn({ + cmd: [bunExe(), "--watch", "script.js"], + env, + cwd: String(dir), + stdout: "pipe", + stderr: "inherit", + stdin: "ignore", + }); + + let i = 0; + for await (const line of proc.stdout) { + const str = new TextDecoder().decode(line); + if (str.includes(`run ${i}`)) { + i++; + if (i === 3) break; // Stop after 3 runs + await Bun.write(join(String(dir), "script.js"), `console.log("run", ${i});`); + } + } + + proc.kill(); + await proc.exited; + + // Check that trace file was created + expect(existsSync(traceFile)).toBe(true); + + const traceContent = readFileSync(traceFile, "utf-8"); + const lines = traceContent + .trim() + .split("\n") + .filter(l => l.trim()); + + // Should have events from watching script.js + expect(lines.length).toBeGreaterThan(0); + + // Validate JSON structure and find script.js events + let foundScriptEvent = false; + for (const line of lines) { + const event = JSON.parse(line); + + // Check required fields exist + expect(event).toHaveProperty("timestamp"); + expect(event).toHaveProperty("index"); + expect(event).toHaveProperty("path"); + expect(event).toHaveProperty("delete"); + expect(event).toHaveProperty("write"); + expect(event).toHaveProperty("rename"); + expect(event).toHaveProperty("metadata"); + expect(event).toHaveProperty("move_to"); + expect(event).toHaveProperty("changed_files"); + + // Validate types + expect(typeof event.timestamp).toBe("number"); + expect(typeof event.index).toBe("number"); + expect(typeof event.path).toBe("string"); + expect(typeof event.delete).toBe("boolean"); + expect(typeof event.write).toBe("boolean"); + expect(typeof event.rename).toBe("boolean"); + expect(typeof event.metadata).toBe("boolean"); + expect(typeof event.move_to).toBe("boolean"); + expect(Array.isArray(event.changed_files)).toBe(true); + + if (event.path.includes("script.js") || event.changed_files.some((f: string) => f?.includes("script.js"))) { + foundScriptEvent = true; + // Should have write flag set + expect(event.write).toBe(true); + } + } + + expect(foundScriptEvent).toBe(true); +}, 10000); + +test("BUN_WATCHER_TRACE with empty path does not create trace", async () => { + using dir = tempDir("watcher-trace-empty", { + "test.js": `console.log("ready");`, + }); + + const env = { ...bunEnv, BUN_WATCHER_TRACE: "" }; + + const proc = Bun.spawn({ + cmd: [bunExe(), "--watch", "test.js"], + env, + cwd: String(dir), + stdout: "pipe", + stderr: "inherit", + stdin: "ignore", + }); + + // Wait for first run, then exit + for await (const line of proc.stdout) { + const str = new TextDecoder().decode(line); + if (str.includes("ready")) { + break; + } + } + + proc.kill(); + await proc.exited; + + // Should not create any trace file in the directory + const files = Array.from(new Bun.Glob("*.log").scanSync({ cwd: String(dir) })); + expect(files.length).toBe(0); +}); + +test("BUN_WATCHER_TRACE appends across reloads", async () => { + using dir = tempDir("watcher-trace-append", { + "app.js": `console.log("first-0");`, + }); + + const traceFile = join(String(dir), "append-trace.log"); + const env = { ...bunEnv, BUN_WATCHER_TRACE: traceFile }; + + // First run + const proc1 = Bun.spawn({ + cmd: [bunExe(), "--watch", "app.js"], + env, + cwd: String(dir), + stdout: "pipe", + stderr: "inherit", + stdin: "ignore", + }); + + let i = 0; + for await (const line of proc1.stdout) { + const str = new TextDecoder().decode(line); + if (str.includes(`first-${i}`)) { + i++; + if (i === 2) break; // Stop after 2 runs + await Bun.write(join(String(dir), "app.js"), `console.log("first-${i}");`); + } + } + + proc1.kill(); + await proc1.exited; + + const firstContent = readFileSync(traceFile, "utf-8"); + const firstLines = firstContent + .trim() + .split("\n") + .filter(l => l.trim()); + expect(firstLines.length).toBeGreaterThan(0); + + // Second run - should append to the same file + const proc2 = Bun.spawn({ + cmd: [bunExe(), "--watch", "app.js"], + env, + cwd: String(dir), + stdout: "pipe", + stderr: "inherit", + stdin: "ignore", + }); + + let j = 0; + for await (const line of proc2.stdout) { + const str = new TextDecoder().decode(line); + if (str.includes(`second-${j}`)) { + j++; + if (j === 2) break; // Stop after 2 runs + await Bun.write(join(String(dir), "app.js"), `console.log("second-${j}");`); + } else if (str.includes("first-1")) { + // Initial run, start modifying + await Bun.write(join(String(dir), "app.js"), `console.log("second-0");`); + } + } + + proc2.kill(); + await proc2.exited; + + const secondContent = readFileSync(traceFile, "utf-8"); + const secondLines = secondContent + .trim() + .split("\n") + .filter(l => l.trim()); + + // Should have more lines after second run + expect(secondLines.length).toBeGreaterThan(firstLines.length); + + // All lines should be valid JSON + for (const line of secondLines) { + const event = JSON.parse(line); + expect(event).toHaveProperty("timestamp"); + expect(event).toHaveProperty("path"); + } +}, 10000);