Append precise UTC timestamps to Rig logs

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).
 

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 {

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",