From 3f2ae4ed9c34c4443efa8bbef7c7c0d580e61459 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 13 Oct 2026 13:03:52 +0000 Subject: [PATCH 1/3] Append precise UTC timestamps to Rig log records Co-authored-by: pelikhan <4175913+pelikhan@users.noreply.github.com> --- skills/rig/debugging.md | 2 ++ skills/rig/rig.ts | 4 ++-- src/rig.test.ts | 47 +++++++++++++++++++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 2 deletions(-) diff --git a/skills/rig/debugging.md b/skills/rig/debugging.md index 19ded2f..ec06543 100644 --- a/skills/rig/debugging.md +++ b/skills/rig/debugging.md @@ -10,6 +10,8 @@ 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 ends with a `timestamp` field: a UTC ISO 8601 string with +millisecond precision (for example, `2026-10-13T13:00:41.033Z`). 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..c85c54d 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; timestamp: string } { + return { type: `rig.${type}`, data, timestamp: new Date().toISOString() }; } function writeDebugLine(line: string): void { diff --git a/src/rig.test.ts b/src/rig.test.ts index 062c259..7e2b7dc 100644 --- a/src/rig.test.ts +++ b/src/rig.test.ts @@ -113,6 +113,7 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:turn", data: { turn: 1 }, + timestamp: expect.any(String), }); }); @@ -123,6 +124,50 @@ describe("debug logging", () => { expect(debug("agent:turn").enabled).toBe(false); }); + it("appends a precise UTC timestamp as the last field of each record", () => { + process.env["RIG_DEBUG"] = "*"; + vi.spyOn(Date.prototype, "toISOString") + .mockReturnValueOnce("2026-10-13T13:00:41.033Z") + .mockReturnValueOnce("2026-10-13T13:00:41.033Z") + .mockReturnValueOnce("2026-10-13T13:00:41.034Z"); + const log = debug("agent:test"); + + log({ ok: true, 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, timestamp: "payload timestamp" }, + timestamp: "2026-10-13T13:00:41.033Z", + }); + expect(events[1]).toEqual({ + type: "rig.agent:test", + timestamp: "2026-10-13T13:00:41.033Z", + }); + expect(events[2].timestamp).toBe("2026-10-13T13:00:41.034Z"); + for (const event of events) { + expect(Object.keys(event).at(-1)).toBe("timestamp"); + } + }); + + it("timestamps serialization error records as their last field", () => { + process.env["RIG_DEBUG"] = "*"; + 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) }, + timestamp: expect.stringMatching(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/), + }); + 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 +234,7 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:tools", data: { agent: "tool-debug", tools: ["lookup"] }, + timestamp: expect.any(String), }); }); }); @@ -434,6 +480,7 @@ describe("agent invocation", () => { expect(logs[0]).toEqual({ type: "rig.engine:copilot:event", data: { type: "session.idle", data: { done: true } }, + timestamp: expect.any(String), }); expect(logs[1]).toMatchObject({ type: "rig.engine:copilot:ask", From 04cecaba5e06110e5e21089ac3884d9018fbf95b Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 13 Oct 2026 13:23:21 +0000 Subject: [PATCH 2/3] Use performance.now for high-resolution Rig log timestamps Co-authored-by: pelikhan <4175913+pelikhan@users.noreply.github.com> --- skills/rig/debugging.md | 4 ++-- skills/rig/rig.ts | 4 ++-- src/rig.test.ts | 25 +++++++++++++------------ 3 files changed, 17 insertions(+), 16 deletions(-) diff --git a/skills/rig/debugging.md b/skills/rig/debugging.md index ec06543..881e7e7 100644 --- a/skills/rig/debugging.md +++ b/skills/rig/debugging.md @@ -10,8 +10,8 @@ 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 ends with a `timestamp` field: a UTC ISO 8601 string with -millisecond precision (for example, `2026-10-13T13:00:41.033Z`). +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 c85c54d..7a7b744 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; timestamp: string } { - return { type: `rig.${type}`, data, timestamp: new Date().toISOString() }; +function rigEvent(type: string, data?: unknown): { type: string; data?: unknown; timestamp: number } { + return { type: `rig.${type}`, data, timestamp: performance.now() }; } function writeDebugLine(line: string): void { diff --git a/src/rig.test.ts b/src/rig.test.ts index 7e2b7dc..4903e80 100644 --- a/src/rig.test.ts +++ b/src/rig.test.ts @@ -113,7 +113,7 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:turn", data: { turn: 1 }, - timestamp: expect.any(String), + timestamp: expect.any(Number), }); }); @@ -124,12 +124,12 @@ describe("debug logging", () => { expect(debug("agent:turn").enabled).toBe(false); }); - it("appends a precise UTC timestamp as the last field of each record", () => { + it("appends a high-resolution performance timestamp as the last field of each record", () => { process.env["RIG_DEBUG"] = "*"; - vi.spyOn(Date.prototype, "toISOString") - .mockReturnValueOnce("2026-10-13T13:00:41.033Z") - .mockReturnValueOnce("2026-10-13T13:00:41.033Z") - .mockReturnValueOnce("2026-10-13T13:00:41.034Z"); + vi.spyOn(performance, "now") + .mockReturnValueOnce(123.456789) + .mockReturnValueOnce(123.456789) + .mockReturnValueOnce(123.456790); const log = debug("agent:test"); log({ ok: true, timestamp: "payload timestamp" }); @@ -140,13 +140,13 @@ describe("debug logging", () => { expect(events[0]).toEqual({ type: "rig.agent:test", data: { ok: true, timestamp: "payload timestamp" }, - timestamp: "2026-10-13T13:00:41.033Z", + timestamp: 123.456789, }); expect(events[1]).toEqual({ type: "rig.agent:test", - timestamp: "2026-10-13T13:00:41.033Z", + timestamp: 123.456789, }); - expect(events[2].timestamp).toBe("2026-10-13T13:00:41.034Z"); + expect(events[2].timestamp).toBe(123.456790); for (const event of events) { expect(Object.keys(event).at(-1)).toBe("timestamp"); } @@ -154,6 +154,7 @@ describe("debug logging", () => { it("timestamps serialization error records as their last field", () => { process.env["RIG_DEBUG"] = "*"; + vi.spyOn(performance, "now").mockReturnValue(123.456789); const data: { self?: unknown } = {}; data.self = data; @@ -163,7 +164,7 @@ describe("debug logging", () => { expect(event).toEqual({ type: "rig.logger.error", data: { error: expect.any(String) }, - timestamp: expect.stringMatching(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/), + timestamp: 123.456789, }); expect(Object.keys(event).at(-1)).toBe("timestamp"); }); @@ -234,7 +235,7 @@ describe("debug logging", () => { expect(JSON.parse(String(fsMocks.writeSync.mock.calls[0]?.[1]))).toEqual({ type: "rig.agent:tools", data: { agent: "tool-debug", tools: ["lookup"] }, - timestamp: expect.any(String), + timestamp: expect.any(Number), }); }); }); @@ -480,7 +481,7 @@ describe("agent invocation", () => { expect(logs[0]).toEqual({ type: "rig.engine:copilot:event", data: { type: "session.idle", data: { done: true } }, - timestamp: expect.any(String), + timestamp: expect.any(Number), }); expect(logs[1]).toMatchObject({ type: "rig.engine:copilot:ask", From 6255600d38affbd988ccd7b0466d495e9e08b15c Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 13 Oct 2026 13:46:42 +0000 Subject: [PATCH 3/3] Add wall-clock created_at to Rig log records Co-authored-by: pelikhan <4175913+pelikhan@users.noreply.github.com> --- skills/rig/debugging.md | 2 ++ skills/rig/rig.ts | 4 ++-- src/rig.test.ts | 17 +++++++++++++++-- 3 files changed, 19 insertions(+), 4 deletions(-) diff --git a/skills/rig/debugging.md b/skills/rig/debugging.md index 881e7e7..d1e85e2 100644 --- a/skills/rig/debugging.md +++ b/skills/rig/debugging.md @@ -10,6 +10,8 @@ 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 diff --git a/skills/rig/rig.ts b/skills/rig/rig.ts index 7a7b744..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; timestamp: number } { - return { type: `rig.${type}`, data, timestamp: performance.now() }; +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 4903e80..15e0ecf 100644 --- a/src/rig.test.ts +++ b/src/rig.test.ts @@ -113,6 +113,7 @@ 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), }); }); @@ -126,34 +127,43 @@ describe("debug logging", () => { 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, timestamp: "payload timestamp" }); + 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, timestamp: "payload timestamp" }, + 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; @@ -164,6 +174,7 @@ describe("debug logging", () => { 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"); @@ -235,6 +246,7 @@ 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), }); }); @@ -481,6 +493,7 @@ 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({