Add BUN_WATCHER_TRACE environment variable for debugging file watcher events

Implements BUN_WATCHER_TRACE env var that logs all file watcher events to a file in JSON format. When set, the watcher appends detailed event information including timestamp, file path, and operation flags (write, delete, rename, metadata, move_to) plus any changed filenames.

The trace file is opened once during watcher initialization in append mode, allowing events to persist across multiple runs of bun --watch or bun --hot. This is useful for debugging watch-related issues.

Example usage:
  BUN_WATCHER_TRACE=/tmp/watch.log bun --watch script.js

Each line in the trace file is a JSON object with:
- timestamp: millisecond timestamp
- index: watch item index
- path: absolute file path being watched
- delete/write/rename/metadata/move_to: boolean operation flags
- changed_files: array of filenames that changed

🤖 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-12 14:56:48 +00:00
parent 85a2ebb717
commit 18ff16dcc7
6 changed files with 405 additions and 0 deletions

View File

@@ -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);
}

View File

@@ -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);
}

View File

@@ -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);
}

View File

@@ -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;
}
}

View File

@@ -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;

View File

@@ -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);