Generated with Hive: Fix canvas agent observability gaps with per-message timestamps, cache-token accounting, timing stats, and AgentLog writes

prisma/migrations/20260728000000_add_cache_token_columns_to_shared_conversations/migration.sql

@@ -0,0 +1,5 @@
+-- AddColumn cache_read_input_tokens to shared_conversations
+ALTER TABLE "shared_conversations" ADD COLUMN "cache_read_input_tokens" INTEGER NOT NULL DEFAULT 0;
+
+-- AddColumn cache_write_input_tokens to shared_conversations
+ALTER TABLE "shared_conversations" ADD COLUMN "cache_write_input_tokens" INTEGER NOT NULL DEFAULT 0;

prisma/schema.prisma

@@ -638,8 +638,14 @@ model SharedConversation {
   // `src/app/api/ask/quick/route.ts`). Output is the dominant cost
   // (~5x input on Anthropic Sonnet); the public rate-limit gate
   // weights it accordingly when summing recent spend.
-  inputTokens        Int               @default(0) @map("input_tokens")
-  outputTokens       Int               @default(0) @map("output_tokens")
+  inputTokens           Int               @default(0) @map("input_tokens")
+  outputTokens          Int               @default(0) @map("output_tokens")
+  // Cache token counters for Anthropic prompt-caching cost tracking.
+  // Cache reads are priced far cheaper than fresh input; cache writes
+  // are slightly more expensive. Tracked separately so the rate-limit
+  // gate can weight them accurately rather than ignoring them.
+  cacheReadInputTokens  Int               @default(0) @map("cache_read_input_tokens")
+  cacheWriteInputTokens Int               @default(0) @map("cache_write_input_tokens")
   createdAt          DateTime          @default(now()) @map("created_at")
   updatedAt          DateTime          @updatedAt @map("updated_at")
   isShared           Boolean           @default(false) @map("is_shared")

src/__tests__/unit/lib/ai/publicChatBudget.test.ts

@@ -1,12 +1,26 @@
-import { describe, it, expect } from "vitest";
+import { describe, it, expect, vi, beforeEach } from "vitest";
 import { NextRequest } from "next/server";
 import {
   ANON_DAILY_TOKEN_CAP,
   OUTPUT_TOKEN_WEIGHT,
+  CACHE_READ_TOKEN_WEIGHT,
+  CACHE_WRITE_TOKEN_WEIGHT,
   WORKSPACE_PUBLIC_DAILY_TOKEN_CAP,
   deriveAnonymousId,
+  recordTurnTokens,
 } from "@/lib/ai/publicChatBudget";
 
+vi.mock("@/lib/db", () => ({
+  db: {
+    sharedConversation: {
+      update: vi.fn().mockResolvedValue({}),
+      aggregate: vi.fn().mockResolvedValue({ _sum: {} }),
+    },
+  },
+}));
+
+import { db } from "@/lib/db";
+
 function makeReq(headers: Record<string, string>): NextRequest {
   return new NextRequest("http://localhost/api/ask/quick", {
     method: "POST",
@@ -64,10 +78,78 @@ describe("token budget constants", () => {
     expect(OUTPUT_TOKEN_WEIGHT).toBe(5);
   });
 
+  it("cache reads are cheaper than fresh input (CACHE_READ_TOKEN_WEIGHT < 1)", () => {
+    // Anthropic prices cache reads at ~10% of fresh input cost.
+    expect(CACHE_READ_TOKEN_WEIGHT).toBeGreaterThan(0);
+    expect(CACHE_READ_TOKEN_WEIGHT).toBeLessThan(1);
+  });
+
+  it("cache writes cost more than fresh input (CACHE_WRITE_TOKEN_WEIGHT > 1)", () => {
+    // Anthropic prices cache writes at ~125% of fresh input cost.
+    expect(CACHE_WRITE_TOKEN_WEIGHT).toBeGreaterThan(1);
+  });
+
   it("per-workspace cap dwarfs per-anon cap", () => {
     // Sanity: a single visitor cannot exhaust the workspace bucket.
     expect(WORKSPACE_PUBLIC_DAILY_TOKEN_CAP).toBeGreaterThan(
       ANON_DAILY_TOKEN_CAP,
     );
   });
 });
+
+describe("recordTurnTokens", () => {
+  const update = db.sharedConversation.update as ReturnType<typeof vi.fn>;
+
+  beforeEach(() => {
+    vi.clearAllMocks();
+  });
+
+  it("persists all four token fields including cache read/write", async () => {
+    await recordTurnTokens({
+      conversationId: "conv-1",
+      inputTokens: 100,
+      outputTokens: 50,
+      cacheReadInputTokens: 200,
+      cacheWriteInputTokens: 30,
+    });
+
+    expect(update).toHaveBeenCalledWith({
+      where: { id: "conv-1" },
+      data: {
+        inputTokens: { increment: 100 },
+        outputTokens: { increment: 50 },
+        cacheReadInputTokens: { increment: 200 },
+        cacheWriteInputTokens: { increment: 30 },
+      },
+    });
+  });
+
+  it("defaults cache fields to 0 when omitted", async () => {
+    await recordTurnTokens({
+      conversationId: "conv-2",
+      inputTokens: 10,
+      outputTokens: 5,
+    });
+
+    expect(update).toHaveBeenCalledWith(
+      expect.objectContaining({
+        data: expect.objectContaining({
+          cacheReadInputTokens: { increment: 0 },
+          cacheWriteInputTokens: { increment: 0 },
+        }),
+      }),
+    );
+  });
+
+  it("skips the DB call when all token counts are zero", async () => {
+    await recordTurnTokens({
+      conversationId: "conv-3",
+      inputTokens: 0,
+      outputTokens: 0,
+      cacheReadInputTokens: 0,
+      cacheWriteInputTokens: 0,
+    });
+
+    expect(update).not.toHaveBeenCalled();
+  });
+});

src/__tests__/unit/lib/ai/runCanvasAgent-timing.test.ts

@@ -413,6 +413,78 @@ describe("runCanvasAgent — stage-timing logs", () => {
     expect(stages).toContain("time-to-first-token");
   });
 
+  // -------------------------------------------------------------------------
+  // 9. timingStats is passed to hooks.onFinish with the correct shape
+  // -------------------------------------------------------------------------
+  it("passes timingStats to hooks.onFinish with ttfMs, toolRoundTrips, durationMs", async () => {
+    const chunks = [
+      { type: "tool-call", toolCallId: "tc1", toolName: "web_search" },
+      { type: "tool-result", toolCallId: "tc1", toolName: "web_search" },
+      { type: "text-delta", text: "answer" },
+    ];
+
+    mockStreamText.mockImplementation(makeStreamResult(chunks));
+
+    const onFinishSpy = vi.fn();
+    await runCanvasAgent(
+      baseOpts({ hooks: { onFinish: onFinishSpy } }),
+    );
+
+    expect(onFinishSpy).toHaveBeenCalledTimes(1);
+    const callArg = onFinishSpy.mock.calls[0][0] as {
+      usage: unknown;
+      timingStats: {
+        ttfMs: number | null;
+        totalToolCalls: number;
+        toolRoundTrips: Array<{ tool: string; ms: number }>;
+        durationMs: number;
+      };
+    };
+
+    // usage is forwarded
+    expect(callArg).toHaveProperty("usage");
+
+    // timingStats is present and well-formed
+    expect(callArg).toHaveProperty("timingStats");
+    const ts = callArg.timingStats;
+
+    // ttfMs: a text-delta was emitted so it should be set (non-null, ≥ 0)
+    expect(ts.ttfMs).not.toBeNull();
+    expect(ts.ttfMs).toBeGreaterThanOrEqual(0);
+
+    // toolRoundTrips: one tool call/result pair was emitted
+    expect(ts.toolRoundTrips).toHaveLength(1);
+    expect(ts.toolRoundTrips[0]).toMatchObject({ tool: "web_search" });
+    expect(ts.toolRoundTrips[0]!.ms).toBeGreaterThanOrEqual(0);
+
+    // totalToolCalls matches toolRoundTrips count
+    expect(ts.totalToolCalls).toBe(1);
+
+    // durationMs is non-negative
+    expect(ts.durationMs).toBeGreaterThanOrEqual(0);
+  });
+
+  it("passes timingStats.ttfMs as null when no text-delta chunks were emitted", async () => {
+    // Tool-only run — no text-delta → ttfMs stays null
+    const chunks = [
+      { type: "tool-call", toolCallId: "tc1", toolName: "list_concepts" },
+      { type: "tool-result", toolCallId: "tc1", toolName: "list_concepts" },
+    ];
+
+    mockStreamText.mockImplementation(makeStreamResult(chunks));
+
+    const onFinishSpy = vi.fn();
+    await runCanvasAgent(
+      baseOpts({ hooks: { onFinish: onFinishSpy } }),
+    );
+
+    const callArg = onFinishSpy.mock.calls[0][0] as {
+      timingStats: { ttfMs: number | null; totalToolCalls: number };
+    };
+    expect(callArg.timingStats.ttfMs).toBeNull();
+    expect(callArg.timingStats.totalToolCalls).toBe(1);
+  });
+
   // -------------------------------------------------------------------------
   // 8. Cache-hit path logs `skipped: "cache hit"` instead of a fetch time
   // -------------------------------------------------------------------------

src/__tests__/unit/lib/utils/agent-log-stats.test.ts

@@ -600,4 +600,85 @@ describe("parseAgentLogStats", () => {
       expect(stats.actualOutputTokens).toBe(40);
     });
   });
+
+  describe("canvas AgentLog blob round-trip", () => {
+    // Tests the serialization shape written by the canvas AgentLog writer
+    // in src/app/api/ask/quick/route.ts → hooks.onFinish (Bug 2 fix).
+    // StoredMessage rows with toolCalls are serialized as AI SDK-format
+    // content[] arrays so parseAgentLogStats can count tool calls, etc.
+    it("round-trips StoredMessage[] with tool-call rows through parseAgentLogStats", () => {
+      // Simulate what the canvas AgentLog writer produces:
+      // one text row + one tool-call row (each StoredMessage with toolCalls
+      // is serialized as content[] with type:"tool-call" + type:"tool-result").
+      const messages = [
+        // Text message
+        {
+          role: "assistant",
+          content: "Looking into it.",
+          timestamp: "2024-01-01T00:00:00.000Z",
+        },
+        // Tool-call message (the flat-map format from the canvas writer)
+        {
+          role: "assistant",
+          timestamp: "2024-01-01T00:00:01.000Z",
+          content: [
+            {
+              type: "tool-call",
+              toolCallId: "tc1",
+              toolName: "web_search",
+              input: { query: "example" },
+            },
+            {
+              type: "tool-result",
+              toolCallId: "tc1",
+              toolName: "web_search",
+              output: { results: [] },
+            },
+          ],
+        },
+        // Second tool in a different row
+        {
+          role: "assistant",
+          timestamp: "2024-01-01T00:00:02.000Z",
+          content: [
+            {
+              type: "tool-call",
+              toolCallId: "tc2",
+              toolName: "list_concepts",
+              input: {},
+            },
+            {
+              type: "tool-result",
+              toolCallId: "tc2",
+              toolName: "list_concepts",
+              output: { concepts: [] },
+            },
+          ],
+        },
+      ];
+
+      // Serialize in the { sessionId, messages } blob shape the canvas writer uses.
+      const blobJson = JSON.stringify({ sessionId: "sess-canvas-1", messages });
+
+      const { stats, conversation } = parseAgentLogStats(blobJson);
+
+      // Two distinct tool calls should be counted.
+      expect(stats.totalToolCalls).toBe(2);
+      expect(stats.toolFrequency).toEqual({ web_search: 1, list_concepts: 1 });
+
+      // The conversation should include all three rows (text + two tool rows).
+      expect(conversation.length).toBe(3);
+
+      // Token estimate is non-zero (text + JSON tool content).
+      expect(stats.estimatedTokens).toBeGreaterThan(0);
+    });
+
+    it("returns zero toolCalls for an empty messages array (the old broken behaviour)", () => {
+      // Empty blob — was produced before the Bug 2 fix.
+      const blobJson = JSON.stringify({ sessionId: "sess-empty", messages: [] });
+      const { stats } = parseAgentLogStats(blobJson);
+      expect(stats.totalToolCalls).toBe(0);
+      expect(stats.totalMessages).toBe(0);
+    });
+  });
 });

src/__tests__/unit/services/canvas-turn-persistence.test.ts

@@ -121,6 +121,56 @@ describe("messagesFromSteps", () => {
       errorText: "Tool call failed",
     });
   });
+
+  test("rows from different steps get distinct timestamps", () => {
+    // Each step in messagesFromSteps() calls `new Date().toISOString()` inside
+    // the for-loop body. The fix moved that call into the loop so different
+    // steps produce different timestamps. This test verifies the fix.
+    //
+    // Strategy: mock the global Date constructor so each instantiation advances
+    // a counter, producing a different ISO string. We don't mock
+    // Date.prototype.toISOString (would cause infinite recursion) — instead we
+    // replace the Date constructor entirely to return controlled dates.
+    const base = new Date("2024-01-01T00:00:00.000Z").getTime();
+    let callCount = 0;
+
+    const OrigDate = Date;
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    const MockDate = function (this: any, ...args: unknown[]) {
+      if (args.length === 0) {
+        // `new Date()` path — the one messagesFromSteps uses.
+        return new OrigDate(base + callCount++ * 60_000);
+      }
+      // Delegate all other usages (e.g. new Date("2024-…")) to the real ctor.
+      return new (OrigDate as unknown as new (...a: unknown[]) => Date)(...args);
+    } as unknown as typeof Date;
+    Object.setPrototypeOf(MockDate, OrigDate);
+    MockDate.prototype = OrigDate.prototype;
+    MockDate.now = OrigDate.now;
+    MockDate.parse = OrigDate.parse;
+    MockDate.UTC = OrigDate.UTC;
+
+    const spy = vi.spyOn(globalThis, "Date").mockImplementation(MockDate);
+
+    try {
+      const steps = [
+        { text: "Step one." },
+        { text: "Step two." },
+        { text: "Step three." },
+      ];
+      const rows = messagesFromSteps(steps, "t-");
+      expect(rows).toHaveLength(3);
+
+      rows.forEach((r) => expect(r.timestamp).toBeDefined());
+
+      // Each step gets a different minute offset → different ISO strings.
+      const timestamps = rows.map((r) => r.timestamp!);
+      const unique = new Set(timestamps);
+      expect(unique.size).toBeGreaterThan(1);
+    } finally {
+      spy.mockRestore();
+    }
+  });
 });
 
 describe("appendTurnMessages", () => {