pt/pf_app
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Record what a write ran against, and the statement it ran

Browse Source 
params says what was asked for. That is not enough to explain a surprising
result, because the same intent produces different rows depending on state
the entry does not carry, and because the translation from intent to SQL is
itself a place bugs live.

So both, not one. env records the state that cannot be reconstructed later:
the territory in force, the version's exclude_iters, and when the template
was generated -- all mutable rows elsewhere with nothing remembering what
they were. sql_text records the statement as executed, territory and scope
already resolved into it.

The template generation is a fingerprint rather than a version. It cannot
bring the old template back; it can tell you the entry did not run under the
current one, which is what would otherwise make a comparison quietly wrong.
Generate SQL has overwritten those templates four times today.

The statement is fetched on demand through GET /log/:logid/debug and left out
of the list, which is opened to scan rather than to read SQL. Under an
entry's payload in the change log there is now an "executed SQL" toggle.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Paul Trowbridge 2026-09-18 12:19:40 -04:00
parent 39b2a7e4a2
commit c6005bd17c
4 changed files with 140 additions and 12 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

30
routes/log.js
View File

@ -92,7 +92,35 @@ module.exports = function(pool) {
);
}
}
res.json(result.rows);
// The statement is kilobytes per entry and the list is opened to scan,
// not to read SQL. It stays in the row for the debug endpoint below.
res.json(result.rows.map(({ sql_text, ...r }) => ({
...r, has_sql: !!sql_text,
})));
} catch (err) {
console.error(err);
res.status(err.status || 500).json({ error: err.message });
}
});
// Everything about one entry, for when the rows look wrong: what was asked
// for (params), what it ran against (env), and the statement that actually
// executed with territory and scope resolved into it (sql_text).
//
// Both the intent and the SQL, because the translation between them is
// exactly what is in doubt when a result is surprising.
router.get('/log/:logid/debug', async (req, res) => {
const logId = parseInt(req.params.logid);
try {
const { rows } = await pool.query(
`SELECT l.*, v.name AS version_name, s.schema, s.tname
FROM pf.log l
JOIN pf.version v ON v.id = l.version_id
JOIN pf.source s ON s.id = v.source_id
WHERE l.id = $1`, [logId]
);
if (!rows.length) return res.status(404).json({ error: 'Log entry not found' });
res.json(rows[0]);
} catch (err) {
console.error(err);
res.status(err.status || 500).json({ error: err.message });

62
routes/operations.js
View File

@ -111,16 +111,30 @@ module.exports = function(pool) {
//
// Best-effort by design. A failure here must not roll back a write that
// succeeded -- the totals can always be recomputed, the adjustment cannot.
async function stampLogTotals(client, ctx, logId) {
async function stampLogTotals(client, ctx, logId, extra = {}) {
if (!logId) return;
const v = ctx.valueCol, u = ctx.unitsCol;
// The state the write ran against, none of which can be reconstructed
// later: territory and exclude_iters are mutable rows elsewhere, and the
// template is overwritten in place every time Generate SQL runs. The
// generation timestamp is a fingerprint, not a version -- it cannot bring
// the old template back, only tell you the entry did not run under this
// one.
const env = {
territory: extra.territory ?? null,
territory_col: ctx.territoryCol || null,
exclude_iters: ctx.version.exclude_iters ?? null,
sql_generated_at: ctx.sqlGeneratedAt || null,
};
try {
await client.query(`
UPDATE pf.log SET
row_count = t.n,
value_total = t.v,
units_total = t.u,
measure_cols = $2::jsonb
measure_cols = $2::jsonb,
env = $3::jsonb,
sql_text = $4::text
FROM (
SELECT count(*)::int AS n
,${v ? `sum(f."${v}")::float8` : 'NULL::float8'} AS v
@ -129,7 +143,8 @@ module.exports = function(pool) {
WHERE f.pf_logid = $1
) t
WHERE pf.log.id = $1
`, [logId, JSON.stringify({ value: v || null, units: u || null })]);
`, [logId, JSON.stringify({ value: v || null, units: u || null }),
JSON.stringify(env), extra.sql || null]);
} catch (err) {
console.error('[stampLogTotals]', err);
}
@ -345,7 +360,7 @@ module.exports = function(pool) {
const unitsCol = colMeta.find(c => c.role === 'units')?.cname;
const sqlResult = await pool.query(
`SELECT sql FROM pf.sql WHERE source_id = $1 AND operation = $2`,
`SELECT sql, generated_at FROM pf.sql WHERE source_id = $1 AND operation = $2`,
[version.source_id, operation]
);
if (sqlResult.rows.length === 0) {
@ -363,7 +378,8 @@ module.exports = function(pool) {
valueCol,
unitsCol,
territoryCol: colMeta.find(c => c.is_territory)?.cname || null,
sql: sqlResult.rows[0].sql
sql: sqlResult.rows[0].sql,
sqlGeneratedAt: sqlResult.rows[0].generated_at
};
}
@ -536,7 +552,7 @@ module.exports = function(pool) {
});
const result = await runSQL(sql);
await stampLogTotals(pool, ctx, result.rows[0]?.log_id);
await stampLogTotals(pool, ctx, result.rows[0]?.log_id, { sql, territory: sessionTerritory(req) });
res.json(result.rows[0]);
} catch (err) {
console.error(err);
@ -617,7 +633,7 @@ module.exports = function(pool) {
await client.query(`DELETE FROM pf.log WHERE id = $1`, [logid]);
const insResult = await client.query(sql);
await client.query('COMMIT');
await stampLogTotals(pool, ctx, insResult.rows[0]?.log_id);
await stampLogTotals(pool, ctx, insResult.rows[0]?.log_id, { sql, territory: sessionTerritory(req) });
res.json({
rows_deleted: delRows.rowCount,
@ -695,7 +711,7 @@ module.exports = function(pool) {
});
const result = await runSQL(sql);
await stampLogTotals(pool, ctx, result.rows[0]?.log_id);
await stampLogTotals(pool, ctx, result.rows[0]?.log_id, { sql, territory: sessionTerritory(req) });
res.json(result.rows[0]);
} catch (err) {
console.error(err);
@ -732,6 +748,8 @@ module.exports = function(pool) {
try {
await client.query('BEGIN');
const allRows = [];
// the statement that produced each entry, for pf.log.sql_text
const sqlByLogId = new Map();
let applied = 0;
const skipped = [];
@ -761,6 +779,9 @@ module.exports = function(pool) {
});
const result = await runSQL(sql, client);
await tagLog(client, result.rows, req.body.tag);
for (const r of result.rows) {
if (r.pf_logid != null) sqlByLogId.set(r.pf_logid, sql);
}
allRows.push(...result.rows);
}
@ -775,7 +796,10 @@ module.exports = function(pool) {
committed = true;
// one log id per unit: apply_mode 'each' writes an entry per slice
for (const id of new Set(allRows.map(r => r.pf_logid).filter(Boolean))) {
await stampLogTotals(pool, ctx, id);
await stampLogTotals(pool, ctx, id, {
sql: sqlByLogId.get(id) || null,
territory: sessionTerritory(req),
});
}
const opLabel = (req.body.tag || '').trim() || note || null;
const rows = allRows.map(r => ({ ...r, pf_segment: ADJUSTMENT_SEGMENT, pf_bucket: ADJUSTMENT_BUCKET, pf_note: opLabel, pf_op: 'scale' }));
@ -819,6 +843,8 @@ module.exports = function(pool) {
try {
await client.query('BEGIN');
const allRows = [];
// the statement that produced each entry, for pf.log.sql_text
const sqlByLogId = new Map();
for (const unit of units) {
const loggedSlice = unit.slices.length === 1 ? unit.slices[0] : unit.slices;
const sql = applyTokens(ctx.sql, {
@ -834,13 +860,19 @@ module.exports = function(pool) {
});
const result = await runSQL(sql, client);
await tagLog(client, result.rows, req.body.tag);
for (const r of result.rows) {
if (r.pf_logid != null) sqlByLogId.set(r.pf_logid, sql);
}
allRows.push(...result.rows);
}
await client.query('COMMIT');
committed = true;
// one log id per unit: apply_mode 'each' writes an entry per slice
for (const id of new Set(allRows.map(r => r.pf_logid).filter(Boolean))) {
await stampLogTotals(pool, ctx, id);
await stampLogTotals(pool, ctx, id, {
sql: sqlByLogId.get(id) || null,
territory: sessionTerritory(req),
});
}
const opLabel = (req.body.tag || '').trim() || note || null;
const rows = allRows.map(r => ({ ...r, pf_segment: ADJUSTMENT_SEGMENT, pf_bucket: ADJUSTMENT_BUCKET, pf_note: opLabel, pf_op: 'recode' }));
@ -912,6 +944,8 @@ module.exports = function(pool) {
try {
await client.query('BEGIN');
const allRows = [];
// the statement that produced each entry, for pf.log.sql_text
const sqlByLogId = new Map();
for (const unit of units) {
const loggedSlice = unit.slices.length === 1 ? unit.slices[0] : unit.slices;
const sql = applyTokens(ctx.sql, {
@ -933,13 +967,19 @@ module.exports = function(pool) {
});
const result = await runSQL(sql, client);
await tagLog(client, result.rows, req.body.tag);
for (const r of result.rows) {
if (r.pf_logid != null) sqlByLogId.set(r.pf_logid, sql);
}
allRows.push(...result.rows);
}
await client.query('COMMIT');
committed = true;
// one log id per unit: apply_mode 'each' writes an entry per slice
for (const id of new Set(allRows.map(r => r.pf_logid).filter(Boolean))) {
await stampLogTotals(pool, ctx, id);
await stampLogTotals(pool, ctx, id, {
sql: sqlByLogId.get(id) || null,
territory: sessionTerritory(req),
});
}
const opLabel = (req.body.tag || '').trim() || note || null;
const rows = allRows.map(r => ({ ...r, pf_segment: ADJUSTMENT_SEGMENT, pf_bucket: ADJUSTMENT_BUCKET, pf_note: opLabel, pf_op: 'clone' }));

19
setup_sql/01_schema.sql
View File

@ -151,6 +151,25 @@ ALTER TABLE pf.log ADD COLUMN IF NOT EXISTS measure_cols jsonb;
-- admin -- moving a row between territories is reassignment, not forecasting.
ALTER TABLE pf.col_meta ADD COLUMN IF NOT EXISTS is_territory boolean NOT NULL DEFAULT false;
-- The debug path: what the entry was trying to do, and what that became.
--
-- Both, deliberately. params records the intent -- the slice, the scope, the
-- resolved increments -- and sql_text records the statement as executed, with
-- territory and scope already resolved into it. Keeping only one of them
-- assumes the translation between them is correct, which is exactly the
-- assumption in doubt when the rows look wrong.
--
-- env captures the state the intent was executed against that cannot be
-- reconstructed afterwards: the territory in force, the version's
-- exclude_iters, and when the template was generated. All three are mutable
-- rows elsewhere, and nothing remembers what they were.
--
-- The template generation is a fingerprint, not a version: it cannot reproduce
-- the old template, but it can tell you the entry ran under a different one,
-- which is what would otherwise make a replay quietly wrong.
ALTER TABLE pf.log ADD COLUMN IF NOT EXISTS env jsonb;
ALTER TABLE pf.log ADD COLUMN IF NOT EXISTS sql_text text;
-- Master data for a dim_group: one row per key value, with its sibling columns.
--
-- The source is transactional and often a view over all history, so deriving a

41
ui/src/views/Forecast.jsx
View File

@ -1976,7 +1976,12 @@ export default function Forecast({ sources = [], sourceId, versions = [], versio
<div className="grid gap-3 md:grid-cols-2">
<LogJson label="slice" value={entry.slice} />
<LogJson label="params" value={entry.params} />
{entry.env && <LogJson label="env" value={entry.env} />}
</div>
{/* The statement is fetched on demand: it is
kilobytes, and the list is opened to scan rather
than to read SQL. */}
{entry.has_sql && <LogSql logId={entry.id} />}
</td>
</tr>
)]
@ -2168,6 +2173,42 @@ function LogCell({ entry, field, placeholder, editing, setEditing, onSave, listI
)
}
// The statement as executed, with territory and scope already resolved into it.
// Read this when the rows look wrong: params says what was asked for, and this
// says what actually ran -- the gap between them being where the bug lives.
function LogSql({ logId }) {
const [sql, setSql] = useState(null)
const [open, setOpen] = useState(false)
const [err, setErr] = useState(null)
async function toggle() {
const next = !open
setOpen(next)
if (next && sql == null && !err) {
try {
const r = await fetch(`/api/log/${logId}/debug`)
const d = await r.json()
if (!r.ok) throw new Error(d.error || 'Could not load the statement')
setSql(d.sql_text || '(not recorded)')
} catch (e) { setErr(e.message) }
}
}
return (
<div className="mt-3">
<button onClick={toggle} className="text-xs text-blue-600 hover:text-blue-700">
{open ? '▾' : '▸'} executed SQL
</button>
{open && (
<pre className="mt-1 font-mono text-[11px] text-gray-600 bg-white border border-gray-200
rounded p-2 overflow-auto max-h-72 leading-relaxed whitespace-pre">
{err || sql || 'Loading…'}
</pre>
)}
</div>
)
}
// Perspective's internal columns, which are never dimensions. Mirrors isMetaColumn()
// in @perspective-dev/viewer-datagrid — the DuckDB backend emits per-level
// __ROW_PATH_<n>__ columns alongside the __ROW_PATH__ sidecar.