diff --git a/skills/rig/debugging.md b/skills/rig/debugging.md index 19ded2f..d1e85e2 100644 --- a/skills/rig/debugging.md +++ b/skills/rig/debugging.md @@ -10,6 +10,10 @@ RIG_DEBUG="engine,agent:turn,-engine:copilot:event" node skills/rig/rig.ts src/p ``` Records are `rig.*` JSONL events on stderr, never the final stdout result. +Each record includes `created_at` from `Date.now()`: wall-clock milliseconds +since the Unix epoch. +Each record ends with a numeric `timestamp` from `performance.now()`: monotonic +milliseconds since the process time origin, with sub-millisecond precision. Do not log credentials. For SDK credential handoff requirements, read [Agentic Workflows](./agentic-workflows.md). diff --git a/skills/rig/rig.ts b/skills/rig/rig.ts index 22c306c..eaa2b58 100644 --- a/skills/rig/rig.ts +++ b/skills/rig/rig.ts @@ -759,8 +759,8 @@ function jsonl(value: unknown): string { } } -function rigEvent(type: string, data?: unknown): { type: string; data?: unknown } { - return { type: `rig.${type}`, data }; +function rigEvent(type: string, data?: unknown): { type: string; data?: unknown; created_at: number; timestamp: number } { + return { type: `rig.${type}`, data, created_at: Date.now(), timestamp: performance.now() }; } function writeDebugLine(line: string): void { diff --git a/src/rig.test.ts b/src/rig.test.ts index 062c259..15e0ecf 100644 --- a/src/rig.test.ts +++ b/src/rig.test.ts @@ -113,6 +113,8 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:turn", data: { turn: 1 }, + created_at: expect.any(Number), + timestamp: expect.any(Number), }); }); @@ -123,6 +125,61 @@ describe("debug logging", () => { expect(debug("agent:turn").enabled).toBe(false); }); + it("appends a high-resolution performance timestamp as the last field of each record", () => { + process.env["RIG_DEBUG"] = "*"; + vi.spyOn(Date, "now") + .mockReturnValueOnce(1791896441033) + .mockReturnValueOnce(1791896441033) + .mockReturnValueOnce(1791896441034); + vi.spyOn(performance, "now") + .mockReturnValueOnce(123.456789) + .mockReturnValueOnce(123.456789) + .mockReturnValueOnce(123.456790); + const log = debug("agent:test"); + + log({ ok: true, created_at: "payload creation time", timestamp: "payload timestamp" }); + log(); + log({ ok: false }); + + const events = fsMocks.writeSync.mock.calls.map(([, line]) => JSON.parse(String(line))); + expect(events[0]).toEqual({ + type: "rig.agent:test", + data: { ok: true, created_at: "payload creation time", timestamp: "payload timestamp" }, + created_at: 1791896441033, + timestamp: 123.456789, + }); + expect(events[1]).toEqual({ + type: "rig.agent:test", + created_at: 1791896441033, + timestamp: 123.456789, + }); + expect(events[2].timestamp).toBe(123.456790); + expect(events[2].created_at).toBe(1791896441034); + for (const event of events) { + expect(Object.keys(event).slice(-2)).toEqual(["created_at", "timestamp"]); + expect(Object.keys(event).at(-1)).toBe("timestamp"); + } + }); + + it("timestamps serialization error records as their last field", () => { + process.env["RIG_DEBUG"] = "*"; + vi.spyOn(Date, "now").mockReturnValue(1791896441033); + vi.spyOn(performance, "now").mockReturnValue(123.456789); + const data: { self?: unknown } = {}; + data.self = data; + + debug("agent:test")(data); + + const event = JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1])); + expect(event).toEqual({ + type: "rig.logger.error", + data: { error: expect.any(String) }, + created_at: 1791896441033, + timestamp: 123.456789, + }); + expect(Object.keys(event).at(-1)).toBe("timestamp"); + }); + it("does not let logging failures affect execution", () => { process.env["RIG_DEBUG"] = "*"; fsMocks.writeSync.mockImplementation(() => { @@ -189,6 +246,8 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:tools", data: { agent: "tool-debug", tools: ["lookup"] }, + created_at: expect.any(Number), + timestamp: expect.any(Number), }); }); }); @@ -434,6 +493,8 @@ describe("agent invocation", () => { expect(logs[0]).toEqual({ type: "rig.engine:copilot:event", data: { type: "session.idle", data: { done: true } }, + created_at: expect.any(Number), + timestamp: expect.any(Number), }); expect(logs[1]).toMatchObject({ type: "rig.engine:copilot:ask",