diff --git a/routes/log.js b/routes/log.js index 94e5e10..bd657c5 100644 --- a/routes/log.js +++ b/routes/log.js @@ -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 }); diff --git a/routes/operations.js b/routes/operations.js index bbea6c2..04d22b7 100644 --- a/routes/operations.js +++ b/routes/operations.js @@ -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' })); diff --git a/setup_sql/01_schema.sql b/setup_sql/01_schema.sql index 3cb6f48..c0a8169 100644 --- a/setup_sql/01_schema.sql +++ b/setup_sql/01_schema.sql @@ -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 diff --git a/ui/src/views/Forecast.jsx b/ui/src/views/Forecast.jsx index c588132..4de19c6 100644 --- a/ui/src/views/Forecast.jsx +++ b/ui/src/views/Forecast.jsx @@ -1976,7 +1976,12 @@ export default function Forecast({ sources = [], sourceId, versions = [], versio
+ {entry.env && }
+ {/* The statement is fetched on demand: it is + kilobytes, and the list is opened to scan rather + than to read SQL. */} + {entry.has_sql && } )] @@ -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 ( +
+ + {open && ( + 
+          {err || sql || 'Loading…'}
+
+ )} +
+ ) +} + // Perspective's internal columns, which are never dimensions. Mirrors isMetaColumn() // in @perspective-dev/viewer-datagrid — the DuckDB backend emits per-level // __ROW_PATH___ columns alongside the __ROW_PATH__ sidecar.