Walk the audit trail without skipping rows written in the same millisecond

CHANGELOG.md

@@ -8,6 +8,15 @@ Newest first. `Unreleased` is what is on `main` and not yet tagged.
 
 ## Unreleased
 
+### Paging the audit trail no longer skips rows written in the same millisecond
+
+`GET /api/admin/audit-events` hands out a `nextCursor` built from the last row's timestamp, which the
+server read at millisecond precision while PostgreSQL keeps microseconds. The cursor therefore named a
+moment just before that row, and the rows the next page should have started with, written earlier in
+the same millisecond, were on no page at all. Anything that walked the trail page by page could miss
+them without any sign of it. The cursor now carries the row's full timestamp. A cursor issued before
+this change still reads.
+
 ### The New chat shortcut works on a Russian or Greek keyboard layout
 
 Settings lists New chat as Shift+N, and the app matched the character the keystroke wrote. A layout

server/src/audit.ts

@@ -1,4 +1,14 @@
-import { and, desc, eq, gt, inArray, lt, or, sql } from "drizzle-orm";
+import {
+  and,
+  desc,
+  eq,
+  getTableColumns,
+  gt,
+  inArray,
+  lt,
+  or,
+  sql,
+} from "drizzle-orm";
 import type { PgColumn } from "drizzle-orm/pg-core";
 import type { Database } from "./db/client";
 import { auditEvents } from "./db/schema";
@@ -717,19 +727,33 @@ export function createAuditReader(database: Database): AuditReader {
       const cursor = query.cursor ? decodeCursor(query.cursor) : undefined;
 
       if (cursor) {
+        // Bound as text and cast by PostgreSQL, not as a `Date`, which would drop the microseconds
+        // the cursor below carries.
+        const createdAt = sql`${cursor.createdAt}::timestamptz`;
         conditions.push(
           or(
-            lt(auditEvents.createdAt, new Date(cursor.createdAt)),
+            lt(auditEvents.createdAt, createdAt),
             and(
-              eq(auditEvents.createdAt, new Date(cursor.createdAt)),
+              eq(auditEvents.createdAt, createdAt),
               lt(auditEvents.id, cursor.id),
             ),
           ),
         );
       }
 
       const rows = await database
-        .select()
+        .select({
+          ...getTableColumns(auditEvents),
+          /*
+           * The row's own timestamp to the microsecond, for the cursor only.
+           *
+           * `created_at` keeps microseconds and a `Date` keeps milliseconds, so a cursor made from
+           * `createdAt` named a moment just before the row it came from. The rows the next page
+           * should have started with, written earlier in that same millisecond or at the same
+           * instant, then compared as newer than the cursor and were on no page at all.
+           */
+          cursorCreatedAt: sql<string>`to_char(${auditEvents.createdAt} at time zone 'UTC', 'YYYY-MM-DD"T"HH24:MI:SS.US"Z"')`,
+        })
         .from(auditEvents)
         .where(and(...conditions))
         .orderBy(desc(auditEvents.createdAt), desc(auditEvents.id))
@@ -739,7 +763,7 @@ export function createAuditReader(database: Database): AuditReader {
       const last = page.at(-1);
 
       return {
-        events: page.map((event) => ({
+        events: page.map(({ cursorCreatedAt: _cursorOnly, ...event }) => ({
           ...event,
           createdAt: event.createdAt.toISOString(),
           payload: event.payload as Record<string, unknown>,
@@ -748,7 +772,7 @@ export function createAuditReader(database: Database): AuditReader {
           hasNextPage && last
             ? encodeCursor({
                 id: last.id,
-                createdAt: last.createdAt.toISOString(),
+                createdAt: last.cursorCreatedAt,
               })
             : undefined,
       };

server/tests/audit-cursor.integration.test.ts

@@ -1,8 +1,10 @@
 import { describe, expect, test } from "bun:test";
+import { sql } from "drizzle-orm";
 import { createApp } from "../src/app";
 import { createAuditReader } from "../src/audit";
 import { loadConfig } from "../src/config";
 import { createDatabase } from "../src/db/client";
+import { auditEvents } from "../src/db/schema";
 import { TEST_POOL, testDatabaseUrl } from "./support/database";
 import { testEnvironment } from "./support/environment";
 
@@ -93,3 +95,66 @@ describe("a cursor the trail's own columns have to parse", () => {
     expect(await response.json()).toHaveProperty("events");
   });
 });
+
+/**
+ * Walking the trail with the cursor the endpoint itself hands out.
+ *
+ * `created_at` keeps microseconds and a JavaScript `Date` keeps milliseconds, so a cursor built from
+ * the row as the driver returns it names a moment slightly before the row it was taken from. Rows
+ * written in the same millisecond as the last one on a page then compare as newer than the cursor
+ * and never come back on any page.
+ */
+describe("a cursor over rows written within one millisecond", () => {
+  const reader = createAuditReader(database);
+
+  /** Rows in one statement, so they share `now()`, at the given microsecond offsets into its millisecond. */
+  async function rowsAt(targetId: string, micros: number[]) {
+    return database
+      .insert(auditEvents)
+      .values(
+        micros.map((offset) => ({
+          eventType: "configuration.changed",
+          targetType: "audit_cursor_test",
+          targetId,
+          payload: {},
+          createdAt: sql`date_trunc('milliseconds', now()) + ${offset}::int * interval '1 microsecond'`,
+        })),
+      )
+      .returning({ id: auditEvents.id });
+  }
+
+  async function walk(targetId: string) {
+    const seen: string[] = [];
+    let cursor: string | undefined;
+    for (let page = 0; page < 10; page += 1) {
+      const result = await reader.list({
+        targetId,
+        limit: 1,
+        ...(cursor ? { cursor } : {}),
+      });
+      seen.push(...result.events.map((event) => event.id));
+      if (!result.nextCursor) break;
+      cursor = result.nextCursor;
+    }
+    return seen;
+  }
+
+  test("reaches every row, newest first, when they are microseconds apart", async () => {
+    const targetId = `cursor-precision-${crypto.randomUUID()}`;
+    const [newest, middle, oldest] = await rowsAt(targetId, [789, 456, 123]);
+
+    expect(await walk(targetId)).toEqual([newest?.id, middle?.id, oldest?.id]);
+  });
+
+  test("reaches every row when they share one instant", async () => {
+    const targetId = `cursor-precision-${crypto.randomUUID()}`;
+    const rows = await rowsAt(targetId, [456, 456, 456]);
+    // One instant, so the id alone orders them, descending as the reader does.
+    const expected = rows
+      .map((row) => row.id)
+      .sort()
+      .reverse();
+
+    expect(await walk(targetId)).toEqual(expected);
+  });
+});