Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 25 additions & 0 deletions .changeset/read-audit-preserve-view-instant.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,25 @@
---
'@objectstack/plugin-audit': patch
---

fix(plugin-audit): record-view rows keep the VIEW instant instead of the buffer-drain instant (#16829)

`sys_audit_log`'s `record_views` rows answer "when did this user look at this record?". Read auditing batches its INSERTs off the request path by design, so `buildRow` writes `created_at: event.viewedAt` rather than letting the column's `NOW()` default stamp a whole batch with one flush timestamp — up to `flushIntervalMs` after the fact, with read order inside the window destroyed.

`persistReadAuditRows` wrote that row under `{ context: { isSystem: true } }`, and the module's comment cited that flag as what carried the view instant through. It never was. `isSystem` exempts a write from the readonly strip; the layer that decides `created_at` on an insert is the audit stamp hook `sys_stamp_audit_insert`, which reads `session.preserveAudit` and has never read `isSystem`. What was actually carrying the value was that hook's pre-#15964 line, `record.created_at = record.created_at ?? now` — client-preferred on every insert, with no flag and no privilege required. #15964 closed that accident (maintainer ruling 2026-09-06), and the ordinary branch has stamped `now` since: on this path, the flush instant.

The write now declares both context keys, for two different layers:

```ts
await engine.insert(
'sys_audit_log',
rows as any,
{ context: { isSystem: true, preserveAudit: true } } as any,
);
```

`isSystem` still carries the readonly-strip exemption the row needs; `preserveAudit` is the one the stamp hook reads. `preserveAudit` is the ruled historical-import channel (#3493, reaffirmed by #15964's ruling) — the door audit left open for reinstating an original timeline — and a view row's original timeline is the moment of the view, so this use is inside its declared purpose rather than a bypass of it.

**What changes for a deployment.** Only for deployments that opted objects in to record-view auditing (`AuditPlugin`'s `readAudit.objects`). Rows written from now on carry the view instant. ⛔ Rows already written under the flattened behaviour are not repaired by this change: their `created_at` is the drain time of the batch they were in, and the view instant they should have carried was never persisted anywhere else, so it cannot be recovered. Only builds cut from `main` after #15964 are affected — the objectql half has not shipped in a published version.

**No exported symbol, schema, route or config key moves.** The only observable change is that a `created_at` this writer already intended to write now survives.
1 change: 1 addition & 0 deletions packages/plugins/plugin-audit/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@
"@objectstack/spec": "workspace:*"
},
"devDependencies": {
"@objectstack/driver-sqlite-wasm": "workspace:*",
"@types/node": "^26.2.0",
"tsx": "^4.23.12",
"typescript": "^6.0.3",
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,278 @@
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.

/**
* [#16829] The record-view ledger keeps the VIEW instant, measured through the
* REAL `sys_stamp_audit_insert` hook.
*
* ## Why this file exists next to a suite that already claims this
*
* `read-audit.test.ts` has a case named `records the VIEW instant, not the
* flush instant`. It builds its engine as a bare `new ObjectQL()` over a stub
* driver — no {@link ObjectQLPlugin} — and `sys_stamp_audit_insert` is
* registered by that PLUGIN (`packages/objectql/src/plugin.ts`, `builtinHooks`
* bound as `sys:audit`), never by the engine. So no audit stamp hook runs in
* that harness at all: whatever `created_at` the writer puts on the row is what
* the driver stores, on BOTH sides of any change to the write's context. The
* case is green today, was green before #15964 flattened the ordinary insert
* branch, and stays green after this card's fix. An instrument that cannot fail
* is indistinguishable from a pass — the same shape that let
* `migrate-sys-notification-to-event.test.ts` read `23 passed` for #16312 while
* the rows it described were being restamped.
*
* ⇒ this file is the instrument that CAN fail. It boots a real
* {@link ObjectKernel} with the real {@link ObjectQLPlugin} (so the shipped
* audit stamp hooks are registered) over a real {@link SqliteWasmDriver}, and
* reads the persisted row back through the driver's own SQL surface.
*
* ⚠️ Unlike #16312's equivalent (`packages/runtime/src/notification-migration-
* audit-preservation.integration.test.ts`), this one lives beside the code it
* tests. That file had to leave `packages/metadata` because
* `@objectstack/objectql` depends on it and the test-only import would have
* closed a cycle. Here the edge already runs the other way —
* `@objectstack/plugin-audit` depends on `@objectstack/objectql` — and
* `@objectstack/driver-sqlite-wasm` depends on neither, so the harness is
* expressible in this package with a devDependency and no cycle.
*
* ## The defect
*
* `buildRow` writes `created_at: event.viewedAt` on purpose: batching moves the
* INSERT off the request path, so `created_at`'s `NOW()` default would stamp a
* whole batch with one buffer-drain time. `persistReadAuditRows` wrote that row
* under `{ context: { isSystem: true } }` and the module's comment cited that
* flag as the mechanism carrying the view instant through. It never was.
* `isSystem` exempts a write from the READONLY STRIP; the stamp hook reads
* `session.preserveAudit` and nothing else. Before #15964 the hook's line was
* `record.created_at = record.created_at ?? now` — client-preferred on EVERY
* insert, no flag required — and that accident is what was actually carrying
* `event.viewedAt`. With #15964's ternary in place the ordinary branch stamps
* `now`, i.e. the flush instant: precisely the outcome the field exists to
* prevent.
*
* ## The three readings, and why the first two are load-bearing
*
* The two `control` cases are ANTI-VACUITY controls, and they are green on both
* sides of the fix by design:
*
* 1. `isSystem` alone does NOT keep a supplied `created_at` — the card's
* central claim, asserted directly on the very write path the ledger uses.
* It is also the proof that the real hook is LIVE in this fixture: delete
* `ObjectQLPlugin` from the boot and this case goes red first, by name.
* 2. `preserveAudit` DOES keep it, on this object and this write path. Without
* it a green third case could mean "the channel happens to be open" rather
* than "the writer declared it".
*
* Only the third case moves with the fix.
*/

import { describe, it, expect, beforeAll, afterAll } from 'vitest';
import { ObjectKernel } from '@objectstack/core';
import { ObjectQL, ObjectQLPlugin } from '@objectstack/objectql';
import { SqliteWasmDriver } from '@objectstack/driver-sqlite-wasm';

import { installReadAuditWriter, READ_AUDIT_ACTION } from './read-audit.js';
import { SysAuditLog } from './objects/index.js';

/** The ledger under test — the REAL shipped object definition, not a stand-in. */
const LEDGER = 'sys_audit_log';
/** The audited business object. */
const AUDITED_OBJECT = 'contact';
const RECORD_ID = 'c_16829';
const VIEWER_ID = 'u_alice';

/** Owning package for the harness objects — `registerObject` requires one. */
const HARNESS_PACKAGE = 'com.objectstack.audit.test';

/**
* Deliberately years in the past, and NOT round.
*
* The verdict is "is the view instant, or the buffer-drain instant, on the
* row?" — so the two must never be within a clock skew of each other, and
* `not.toBe(flushInstant)` is not what discriminates: the positive equality is.
*/
const VIEW_INSTANT = new Date('2019-03-04T05:06:07.891Z');
/** A second past instant, for the two control writes. */
const BACKDATED = '2019-03-05T06:07:08.912Z';

const contactObject = {
name: AUDITED_OBJECT,
label: 'Contact',
fields: {
full_name: { name: 'full_name', label: 'Name', type: 'text' as const },
},
};

/** `Date.parse` of a stored value, whatever spelling the driver handed back. */
function instantOf(value: unknown): number {
if (value instanceof Date) return value.getTime();
return Date.parse(String(value));
}

/** knex wraps some results as `[rows]`; normalize both shapes and take the first. */
function firstRow(result: unknown): Record<string, unknown> {
const list = Array.isArray(result) && Array.isArray(result[0]) ? result[0] : result;
expect(Array.isArray(list)).toBe(true);
expect((list as unknown[]).length).toBeGreaterThan(0);
return (list as Record<string, unknown>[])[0]!;
}

describe('[#16829] the record-view ledger keeps the VIEW instant through the real audit stamp hook', () => {
let kernel: ObjectKernel;
let driver: SqliteWasmDriver;
let engine: ObjectQL;
/** Raw SQL through the driver's own surface — the same door an operator has. */
let sql: (statement: string, bindings?: unknown[]) => Promise<unknown>;

beforeAll(async () => {
kernel = new ObjectKernel({ logger: { level: 'silent' } });
await kernel.use(new ObjectQLPlugin());
await kernel.bootstrap();

engine = kernel.getService<ObjectQL>('objectql');

// The engine's own `init()` ran during bootstrap, before this driver
// existed, so the connect the engine would have done is done here.
driver = new SqliteWasmDriver({ filename: ':memory:' });
await driver.connect();
engine.registerDriver(driver, true);
sql = (statement, bindings) =>
(driver as unknown as { execute(s: string, b: unknown[]): Promise<unknown> }).execute(
statement,
bindings ?? [],
);

engine.registry.registerObject(contactObject as any, HARNESS_PACKAGE);
engine.registry.registerObject(SysAuditLog as any, HARNESS_PACKAGE);
// Real DDL for both tables, including the builtin audit timestamp columns.
await engine.syncSchemas();

await engine.insert(
AUDITED_OBJECT,
{ id: RECORD_ID, full_name: 'Wei Zhang' },
{ context: { isSystem: true } },
);
}, 120_000);

afterAll(async () => {
if (kernel) {
await Promise.race([
kernel.shutdown(),
new Promise<void>((resolve) => setTimeout(resolve, 10_000)),
]);
}
}, 30_000);

/**
* ANTI-VACUITY CONTROL, and the card's central claim as a measurement.
*
* The write below is byte-for-byte the context `persistReadAuditRows` used:
* `{ isSystem: true }`, carrying a back-dated `created_at`, onto
* `sys_audit_log`. If `isSystem` were the mechanism the module's comment
* claimed, the supplied instant would survive. It does not — the ordinary
* branch of `sys_stamp_audit_insert` stamps `now`.
*
* ⇒ this is also the proof the shipped hook is LIVE in this fixture. In a
* harness that runs no hooks (`new ObjectQL()` with no plugin — what
* `read-audit.test.ts` builds) this case is the one that goes red.
*/
it('control — a bare `isSystem` write does NOT keep a supplied created_at, so the real stamp hook is live', async () => {
const before = Date.now();
await engine.insert(
LEDGER,
{
action: 'create',
object_name: AUDITED_OBJECT,
record_id: 'rec_control_is_system',
created_at: BACKDATED,
},
{ context: { isSystem: true } },
);

const row = firstRow(
await sql(`SELECT created_at FROM "${LEDGER}" WHERE record_id = ?`, ['rec_control_is_system']),
);
const stored = instantOf(row.created_at);
expect(stored).not.toBe(Date.parse(BACKDATED));
expect(stored).toBeGreaterThanOrEqual(before - 1000);
});

/**
* ANTI-VACUITY CONTROL — the declared historical-import channel is open on
* THIS object and THIS write path.
*
* `preserveAudit` is the ruled channel for reinstating an original timeline
* (#3493, reaffirmed by #15964's ruling of 2026-09-06), not a bypass of
* audit. `sys_audit_log` is `isSystem` + `managedBy: 'append-only'`, so the
* create-side readonly strip exits early on it and the hook's keep is the
* whole story. That reasoning is what this case turns into a measurement:
* without it, a green third case could not distinguish "the writer declared
* the channel" from "nothing was ever going to restamp this row".
*/
it('control — `context.preserveAudit` keeps a supplied created_at on this write path', async () => {
await engine.insert(
LEDGER,
{
action: 'create',
object_name: AUDITED_OBJECT,
record_id: 'rec_control_preserve',
created_at: BACKDATED,
},
{ context: { isSystem: true, preserveAudit: true } },
);

const row = firstRow(
await sql(`SELECT created_at FROM "${LEDGER}" WHERE record_id = ?`, ['rec_control_preserve']),
);
expect(instantOf(row.created_at)).toBe(Date.parse(BACKDATED));
});

/**
* THE CARD. A record-detail view produces a ledger row stamped with the
* VIEW instant, not the instant the batch drained.
*
* RED before the fix: `persistReadAuditRows` passed `{ isSystem: true }`
* only, so the audit hook took its ordinary branch and stamped the flush
* instant on every row in the batch — a ledger that answers "when did they
* look?" with the time its own buffer drained, with read order inside the
* window destroyed.
*
* The clock seam (`now`) is `installReadAuditWriter`'s own declared option,
* so the view instant here is the one the writer would stamp in production,
* moved somewhere no wall clock can wander to.
*/
it('a record-detail view is stamped with the VIEW instant, not the flush instant', async () => {
const writer = installReadAuditWriter(engine, {
objects: [AUDITED_OBJECT],
now: () => VIEW_INSTANT,
});
expect(writer).not.toBeNull();

try {
const flushWindowStart = Date.now();
const seen = await engine.findOne(AUDITED_OBJECT, {
where: { id: RECORD_ID },
context: { userId: VIEWER_ID },
});
// The read itself must have materialized the record — otherwise the
// record-detail discriminator would decline and the absence of a ledger
// row would be about the fixture, not about the stamp.
expect((seen as { id?: string } | null)?.id).toBe(RECORD_ID);

await writer!.flush();
expect(writer!.pending()).toBe(0);

const row = firstRow(
await sql(`SELECT created_at, user_id, record_id FROM "${LEDGER}" WHERE action = ?`, [
READ_AUDIT_ACTION,
]),
);
expect(row.record_id).toBe(RECORD_ID);
expect(row.user_id).toBe(VIEWER_ID);
expect(instantOf(row.created_at)).toBe(VIEW_INSTANT.getTime());
// Stated the other way round too: the row predates the drain it was
// written in, which is the property the whole field exists for.
expect(instantOf(row.created_at)).toBeLessThan(flushWindowStart);
} finally {
await writer!.stop();
}
});
});
41 changes: 34 additions & 7 deletions packages/plugins/plugin-audit/src/read-audit.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -17,9 +17,30 @@
* (`{ object: [...] }`), so "an object that is not opted in produces no
* row" has to be the engine's real dispatch declining to call us;
* - "record-detail views only" turns on the real shapes `find` and `findOne`
* leave on `ctx.result` and `ctx.input.ast.where`;
* - the row keeps the VIEW instant, which depends on the real engine's
* `created_at` strip and its system-context exemption (#4447).
* leave on `ctx.result` and `ctx.input.ast.where`.
*
* ⚠️ [#16829] A THIRD pin used to be claimed here — "the row keeps the VIEW
* instant, which depends on the real engine's `created_at` strip and its
* system-context exemption (#4447)". This file CANNOT make that one, and the
* claim was false in both of its halves.
*
* `makeEngine` below builds a bare `new ObjectQL()`. The audit stamp hooks are
* registered by `ObjectQLPlugin` (`objectql/src/plugin.ts`, `builtinHooks`
* bound as `sys:audit`), never by the engine, so NO stamp hook runs in this
* harness: whatever `created_at` the writer puts on a row is what the stub
* driver stores, on both sides of any change to the write's context. And the
* mechanism named was the wrong one anyway — `isSystem` exempts a write from
* the readonly strip; `created_at` is decided by the stamp hook, which reads
* `preserveAudit` alone.
*
* ⇒ the VIEW-instant case below is kept, but it is a pin on THIS MODULE's own
* behaviour (the writer stamps `viewedAt` rather than leaving the column to the
* engine), ⛔ not on the engine's treatment of that value. The pin that covers
* the engine half is `read-audit-view-instant-preservation.integration.test.ts`
* — a real kernel, the real `ObjectQLPlugin`, a real driver. ⛔ Do not restate
* an engine-behaviour guarantee here: a green reading from an instrument that
* cannot fail is indistinguishable from a pass, and that is precisely how
* #16829 shipped.
*/

import { describe, it, expect, beforeEach } from 'vitest';
Expand Down Expand Up @@ -517,11 +538,17 @@ describe('#8992 what the row must NOT contain, and when it says it happened', ()
/**
* Batching moves the INSERT off the request path, which is exactly what makes
* `created_at`'s `NOW()` default wrong here: it would stamp the whole batch
* with the moment the buffer drained. The engine strips a client-supplied
* `created_at` from ordinary writes (#4447) and exempts system-context writes
* — the writer relies on that exemption, so this pins both halves.
* with the moment the buffer drained. So the writer puts `viewedAt` on the
* row itself rather than leaving the column to the engine — and that, the
* writer's own behaviour, is the whole of what this case pins.
*
* ⛔ [#16829] It does NOT pin that the engine keeps the value. This harness's
* engine registers no audit stamp hook at all (see this file's header), so
* this case reads green whether the ledger write declares `preserveAudit` or
* not. The engine half is pinned by
* `read-audit-view-instant-preservation.integration.test.ts`.
*/
it('records the VIEW instant, not the flush instant', async () => {
it('records the VIEW instant on the row it hands the engine (⛔ see header: no stamp hook runs here)', async () => {
const viewedAt = new Date('2026-08-18T09:15:00.000Z');
const writer = installReadAuditWriter(engine, {
objects: ['contact'],
Expand Down
Loading
Loading