mirror of
https://github.com/cpvalente/ontime.git
synced 2026-08-13 19:33:46 +00:00
fix(report): correct run timestamps, scoping and recovery
Review of the run history feature turned up four defects, all in the code that feature introduced. - Runs were dated with a time of day rather than a wall clock instant. `clock` and `rundown.actualStart` are millis since midnight, so every run in the history list rendered as 1 January 1970, and getLatestRun ordered runs incorrectly across days: a run at 09:00 today sorted below one at 20:00 last week, so the "last run" chip and /runs/latest could return an older run. Runs now take `_startEpoch`, the instant the show began, and the type documents the invariant. - A stop arriving with no run open is ignored. Loading a project stops playback and reinitialises reporting in the same tick, and the trailing stop was attributing the previous project's event to the new one. - Run summaries counted planned events from the loaded rundown rather than the rundown the run belongs to, so switching rundowns mid-run gave the summary a denominator from a different rundown. A run whose rundown has since been deleted now keeps its last known count instead of dropping to zero. - Recovery of runs left open by a crash only closed the first one. Any others stayed dangling forever: permanently shown as ongoing and never eligible as the latest run. Also replaces the raw ISO default run label with a readable local date and time, and adds a batching upsertRuns to the store so recovery writes the sidecar once rather than racing one write per run. Each fix has a regression test, verified to fail without the change. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019nr3FbLbM8gB8Jm771YgTV
This commit is contained in:
@@ -22,6 +22,16 @@ vi.mock('../../../services/report-service/report.store.js', () => ({
|
||||
runs[index] = run;
|
||||
}
|
||||
}),
|
||||
upsertRuns: vi.fn(async (updated: ShowRun[]) => {
|
||||
for (const run of updated) {
|
||||
const index = runs.findIndex((candidate) => candidate.id === run.id);
|
||||
if (index === -1) {
|
||||
runs.unshift(run);
|
||||
} else {
|
||||
runs[index] = run;
|
||||
}
|
||||
}
|
||||
}),
|
||||
deleteRun: vi.fn(async (id: string) => {
|
||||
const index = runs.findIndex((run) => run.id === id);
|
||||
if (index === -1) return false;
|
||||
@@ -39,9 +49,21 @@ vi.mock('../../../services/report-service/report.store.js', () => ({
|
||||
}));
|
||||
|
||||
let currentRundown = makeRundown({ id: 'rundown-1', title: 'Test rundown' });
|
||||
/** rundowns reachable by id, standing in for what is on disk */
|
||||
let storedRundowns: Record<string, ReturnType<typeof makeRundown>> = {};
|
||||
|
||||
vi.mock('../../rundown/rundown.dao.js', () => ({
|
||||
getCurrentRundown: vi.fn(() => currentRundown),
|
||||
getCurrentRundownId: vi.fn(() => currentRundown.id),
|
||||
}));
|
||||
|
||||
vi.mock('../../../classes/data-provider/DataProvider.js', () => ({
|
||||
getDataProvider: vi.fn(() => ({
|
||||
getRundown: vi.fn((id: string) => {
|
||||
if (!(id in storedRundowns)) throw new Error(`Rundown with id: ${id} not found`);
|
||||
return storedRundowns[id];
|
||||
}),
|
||||
})),
|
||||
}));
|
||||
|
||||
const {
|
||||
@@ -70,9 +92,13 @@ beforeEach(async () => {
|
||||
order: [eventA.id, eventB.id],
|
||||
flatOrder: [eventA.id, eventB.id],
|
||||
});
|
||||
storedRundowns = { 'rundown-1': currentRundown };
|
||||
await initReports('project-a');
|
||||
});
|
||||
|
||||
/** an epoch instant, as the runtime would supply on the first event start */
|
||||
const showEpoch = Date.UTC(2026, 7, 8, 9, 30);
|
||||
|
||||
describe('triggerReportEntry()', () => {
|
||||
it('captures a snapshot of the schedule when an event starts', () => {
|
||||
const state = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 500 }, clock: 500 });
|
||||
@@ -118,6 +144,14 @@ describe('triggerReportEntry()', () => {
|
||||
expect(generate()).toEqual({});
|
||||
});
|
||||
|
||||
it('ignores a stop arriving when no run is open', () => {
|
||||
// a project load stops playback and reinitialises reporting, the trailing
|
||||
// stop must not attribute the old project's event to the new one
|
||||
const state = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 10000 });
|
||||
triggerReportEntry(TimerLifeCycle.onStop, state);
|
||||
expect(generate()).toEqual({});
|
||||
});
|
||||
|
||||
it('persists a run to history on the first event stop', async () => {
|
||||
const start = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 0 });
|
||||
triggerReportEntry(TimerLifeCycle.onStart, start);
|
||||
@@ -132,6 +166,67 @@ describe('triggerReportEntry()', () => {
|
||||
});
|
||||
});
|
||||
|
||||
describe('run timestamps', () => {
|
||||
it('dates a run with the wall clock epoch, not the time of day', async () => {
|
||||
// clock/actualStart are millis since midnight, which cannot date a run.
|
||||
// The run must take _startEpoch so it is not stamped 1 Jan 1970.
|
||||
const state = makeRuntimeStateData({
|
||||
eventNow: eventA,
|
||||
timer: { startedAt: 0 },
|
||||
clock: 34200000, // 09:30 as a time of day
|
||||
rundown: { actualStart: 34200000 },
|
||||
_startEpoch: showEpoch,
|
||||
});
|
||||
triggerReportEntry(TimerLifeCycle.onStart, state);
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: 44200000 } as typeof state);
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
|
||||
const run = listRuns()[0];
|
||||
expect(run.startedAt).toBe(showEpoch);
|
||||
expect(new Date(run.startedAt).getUTCFullYear()).toBe(2026);
|
||||
});
|
||||
|
||||
it('falls back to the current instant when no start epoch is available', async () => {
|
||||
const before = Date.now();
|
||||
const state = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 0, _startEpoch: null });
|
||||
triggerReportEntry(TimerLifeCycle.onStart, state);
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: 10000 } as typeof state);
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
|
||||
const run = listRuns()[0];
|
||||
expect(run.startedAt).toBeGreaterThanOrEqual(before);
|
||||
expect(run.startedAt).toBeLessThanOrEqual(Date.now());
|
||||
});
|
||||
|
||||
it('orders runs from different days correctly', async () => {
|
||||
// a run at 09:30 today must rank above one at 20:00 yesterday, which
|
||||
// time-of-day ordering would get backwards
|
||||
const yesterdayEvening = Date.UTC(2026, 7, 7, 20, 0);
|
||||
await makeClosedRunAt('older', yesterdayEvening);
|
||||
await makeClosedRunAt('newer', showEpoch);
|
||||
|
||||
expect(getLatestRun()?.id).toBe('newer');
|
||||
});
|
||||
|
||||
async function makeClosedRunAt(id: string, epoch: number) {
|
||||
// the time of day deliberately disagrees with chronological order here:
|
||||
// 20:00 yesterday is a larger time of day than 09:30 today
|
||||
const timeOfDay = epoch % 86400000;
|
||||
const state = makeRuntimeStateData({
|
||||
eventNow: eventA,
|
||||
timer: { startedAt: 0 },
|
||||
clock: timeOfDay,
|
||||
rundown: { actualStart: timeOfDay },
|
||||
_startEpoch: epoch,
|
||||
});
|
||||
triggerReportEntry(TimerLifeCycle.onStart, state);
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: timeOfDay + 10000 } as typeof state);
|
||||
closeRun();
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
runs[0] = { ...runs[0], id };
|
||||
}
|
||||
});
|
||||
|
||||
describe('closeRun()', () => {
|
||||
it('closes the open run and starts a fresh one on the next event', async () => {
|
||||
const start = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 0 });
|
||||
@@ -197,6 +292,85 @@ describe('initReports()', () => {
|
||||
const recovered = getRun('dangling');
|
||||
expect(recovered?.endedAt).toBe(9000);
|
||||
});
|
||||
|
||||
it('closes every dangling run, not only the first', async () => {
|
||||
runs = [makeDanglingRun('first', 4000), makeDanglingRun('second', 7000)];
|
||||
|
||||
await initReports('project-a');
|
||||
|
||||
expect(getRun('first')?.endedAt).toBe(4000);
|
||||
expect(getRun('second')?.endedAt).toBe(7000);
|
||||
expect(listRuns().every((run) => run.endedAt !== null)).toBe(true);
|
||||
});
|
||||
|
||||
function makeDanglingRun(id: string, endedAt: number): ShowRun {
|
||||
return {
|
||||
id,
|
||||
rundownId: 'rundown-1',
|
||||
rundownTitle: 'Test rundown',
|
||||
label: id,
|
||||
startedAt: showEpoch,
|
||||
endedAt: null,
|
||||
report: {
|
||||
[eventA.id]: { startedAt: 0, endedAt, scheduledStart: 0, scheduledDuration: 10000, playCount: 1 },
|
||||
},
|
||||
summary: {
|
||||
eventsRun: 1,
|
||||
eventsPlanned: 2,
|
||||
scheduledDuration: 10000,
|
||||
actualDuration: endedAt,
|
||||
drift: endedAt - 10000,
|
||||
eventsOver: 0,
|
||||
eventsUnder: 1,
|
||||
eventsOnTime: 0,
|
||||
worstOverrun: null,
|
||||
},
|
||||
};
|
||||
}
|
||||
});
|
||||
|
||||
describe('summary is measured against the run\'s own rundown', () => {
|
||||
it('counts planned events from the rundown the run belongs to', async () => {
|
||||
// a three event rundown that is not the loaded one
|
||||
const otherEvent = makeOntimeEvent({ id: 'event-c', timeStart: 0, timeEnd: 1000, duration: 1000 });
|
||||
storedRundowns['rundown-2'] = makeRundown({
|
||||
id: 'rundown-2',
|
||||
title: 'Other rundown',
|
||||
entries: { [eventA.id]: eventA, [eventB.id]: eventB, [otherEvent.id]: otherEvent },
|
||||
order: [eventA.id, eventB.id, otherEvent.id],
|
||||
flatOrder: [eventA.id, eventB.id, otherEvent.id],
|
||||
});
|
||||
|
||||
// open a run against rundown-2, then switch the loaded rundown away
|
||||
currentRundown = storedRundowns['rundown-2'];
|
||||
const state = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 0, _startEpoch: showEpoch });
|
||||
triggerReportEntry(TimerLifeCycle.onStart, state);
|
||||
currentRundown = storedRundowns['rundown-1'];
|
||||
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: 10000 } as typeof state);
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
|
||||
// three, from rundown-2, not two from the now loaded rundown-1
|
||||
expect(listRuns()[0].summary.eventsPlanned).toBe(3);
|
||||
});
|
||||
|
||||
it('keeps the last known count when the rundown has been deleted', async () => {
|
||||
currentRundown = makeRundown({ id: 'gone', title: 'Deleted rundown', entries: {}, order: [], flatOrder: [] });
|
||||
const state = makeRuntimeStateData({ eventNow: eventA, timer: { startedAt: 0 }, clock: 0, _startEpoch: showEpoch });
|
||||
triggerReportEntry(TimerLifeCycle.onStart, state);
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: 10000 } as typeof state);
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
|
||||
// rundown disappears from both the loaded slot and storage
|
||||
const runId = listRuns()[0].id;
|
||||
runs[0] = { ...runs[0], summary: { ...runs[0].summary, eventsPlanned: 7 } };
|
||||
currentRundown = storedRundowns['rundown-1'];
|
||||
|
||||
triggerReportEntry(TimerLifeCycle.onStop, { ...state, clock: 20000 } as typeof state);
|
||||
await new Promise((resolve) => setImmediate(resolve));
|
||||
|
||||
expect(getRun(runId)?.summary.eventsPlanned).toBe(7);
|
||||
});
|
||||
});
|
||||
|
||||
describe('run history queries and edits', () => {
|
||||
|
||||
@@ -3,6 +3,7 @@ import {
|
||||
OntimeEventReport,
|
||||
OntimeReport,
|
||||
RefetchKey,
|
||||
Rundown,
|
||||
ShowRun,
|
||||
ShowRunSummary,
|
||||
TimerLifeCycle,
|
||||
@@ -11,9 +12,11 @@ import { countPlannedEvents, generateId, getRunSummary } from 'ontime-utils';
|
||||
import { DeepReadonly } from 'ts-essentials';
|
||||
|
||||
import { sendRefetch } from '../../adapters/WebsocketAdapter.js';
|
||||
import { getDataProvider } from '../../classes/data-provider/DataProvider.js';
|
||||
import * as timeCore from '../../lib/time-core/timeCore.js';
|
||||
import * as reportStore from '../../services/report-service/report.store.js';
|
||||
import { RuntimeState } from '../../stores/runtimeState.js';
|
||||
import { getCurrentRundown } from '../rundown/rundown.dao.js';
|
||||
import { getCurrentRundown, getCurrentRundownId } from '../rundown/rundown.dao.js';
|
||||
|
||||
/** per event data for the run currently in progress */
|
||||
const report = new Map<EntryId, OntimeEventReport>();
|
||||
@@ -83,6 +86,13 @@ export function triggerReportEntry(
|
||||
}
|
||||
|
||||
if (cycle === TimerLifeCycle.onStop) {
|
||||
// With no run open there is nothing this event can belong to. A stop can
|
||||
// still arrive here after a project load, and recording it would attribute
|
||||
// the previous project's event to the newly loaded one.
|
||||
if (openRun === null) {
|
||||
return;
|
||||
}
|
||||
|
||||
const previous = report.get(eventId);
|
||||
report.set(eventId, {
|
||||
startedAt: previous?.startedAt ?? null,
|
||||
@@ -109,7 +119,7 @@ export function closeRun() {
|
||||
|
||||
// detach the run before the async write so a start arriving in between
|
||||
// opens a new run instead of appending to the one we are closing
|
||||
const closing = { ...openRun, endedAt: lastEndedAt() };
|
||||
const closing = { ...openRun, endedAt: lastEndedAtIn(generate()) };
|
||||
openRun = null;
|
||||
|
||||
void persistRun(closing, generate());
|
||||
@@ -131,18 +141,33 @@ function openRunIfNeeded(state: DeepReadonly<RuntimeState>) {
|
||||
formattedReport = null;
|
||||
|
||||
const rundown = getCurrentRundown();
|
||||
const startedAt = state.rundown.actualStart ?? state.clock;
|
||||
// `clock` and `rundown.actualStart` are times of day, which cannot date or
|
||||
// order a run across days. `_startEpoch` is the wall clock instant the show
|
||||
// began, which is what a run needs to be a dated record.
|
||||
const startedAt = state._startEpoch ?? timeCore.now();
|
||||
|
||||
openRun = {
|
||||
id: generateId(),
|
||||
rundownId: rundown.id,
|
||||
rundownTitle: rundown.title,
|
||||
label: new Date().toISOString(),
|
||||
label: makeRunLabel(startedAt),
|
||||
startedAt,
|
||||
endedAt: null,
|
||||
};
|
||||
}
|
||||
|
||||
/**
|
||||
* Default name for a run, a readable local date and time rather than the
|
||||
* raw timestamp the user would otherwise have to decipher.
|
||||
* @private
|
||||
*/
|
||||
function makeRunLabel(startedAt: number): string {
|
||||
return new Date(startedAt).toLocaleString(undefined, {
|
||||
dateStyle: 'medium',
|
||||
timeStyle: 'short',
|
||||
});
|
||||
}
|
||||
|
||||
/**
|
||||
* Writes the run in progress to the sidecar.
|
||||
* Persisting on every event stop means an interrupted show still leaves a record.
|
||||
@@ -160,8 +185,12 @@ async function persistOpenRun(): Promise<void> {
|
||||
* @private
|
||||
*/
|
||||
async function persistRun(run: Omit<ShowRun, 'report' | 'summary'>, currentReport: OntimeReport): Promise<void> {
|
||||
const rundown = getCurrentRundown();
|
||||
const eventsPlanned = countPlannedEvents(rundown.entries, rundown.flatOrder);
|
||||
const rundown = getRundownForRun(run.rundownId);
|
||||
// a rundown deleted mid-run leaves nothing to count against, so we keep
|
||||
// whatever the run was last written with rather than reporting zero
|
||||
const eventsPlanned = rundown
|
||||
? countPlannedEvents(rundown.entries, rundown.flatOrder)
|
||||
: (reportStore.getRun(run.id)?.summary.eventsPlanned ?? 0);
|
||||
|
||||
await reportStore.upsertRun({
|
||||
...run,
|
||||
@@ -171,17 +200,22 @@ async function persistRun(run: Omit<ShowRun, 'report' | 'summary'>, currentRepor
|
||||
}
|
||||
|
||||
/**
|
||||
* Timestamp of the last event to finish in this run
|
||||
* Resolves the rundown a run belongs to.
|
||||
* The loaded rundown can be switched while a run is open, so the run's own
|
||||
* id is the only reliable way to count the events it was measured against.
|
||||
* @private
|
||||
*/
|
||||
function lastEndedAt(): number | null {
|
||||
let latest: number | null = null;
|
||||
for (const entry of report.values()) {
|
||||
if (entry.endedAt !== null && (latest === null || entry.endedAt > latest)) {
|
||||
latest = entry.endedAt;
|
||||
}
|
||||
function getRundownForRun(rundownId: string): Readonly<Rundown> | null {
|
||||
if (rundownId === getCurrentRundownId()) {
|
||||
return getCurrentRundown();
|
||||
}
|
||||
|
||||
try {
|
||||
return getDataProvider().getRundown(rundownId);
|
||||
} catch (_error) {
|
||||
// getRundown throws when the rundown no longer exists
|
||||
return null;
|
||||
}
|
||||
return latest;
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -196,14 +230,28 @@ export async function initReports(projectFilename: string): Promise<void> {
|
||||
|
||||
await reportStore.loadReports(projectFilename);
|
||||
|
||||
const dangling = reportStore.getRuns().find((run) => run.endedAt === null);
|
||||
if (dangling) {
|
||||
const endedAt = Object.values(dangling.report).reduce<number | null>((latest, entry) => {
|
||||
if (entry.endedAt === null) return latest;
|
||||
return latest === null || entry.endedAt > latest ? entry.endedAt : latest;
|
||||
}, null);
|
||||
await reportStore.upsertRun({ ...dangling, endedAt });
|
||||
// close every run left open, not just the first: a run stuck with a null
|
||||
// endedAt reads as ongoing forever and is skipped by getLatestRun
|
||||
const closed: ShowRun[] = [];
|
||||
for (const run of reportStore.getRuns()) {
|
||||
if (run.endedAt !== null) continue;
|
||||
closed.push({ ...run, endedAt: lastEndedAtIn(run.report) });
|
||||
}
|
||||
await reportStore.upsertRuns(closed);
|
||||
}
|
||||
|
||||
/**
|
||||
* Timestamp of the last event to finish within a stored report
|
||||
* @private
|
||||
*/
|
||||
function lastEndedAtIn(storedReport: OntimeReport): number | null {
|
||||
let latest: number | null = null;
|
||||
for (const entry of Object.values(storedReport)) {
|
||||
if (entry.endedAt !== null && (latest === null || entry.endedAt > latest)) {
|
||||
latest = entry.endedAt;
|
||||
}
|
||||
}
|
||||
return latest;
|
||||
}
|
||||
|
||||
/** Run history for the current project, without per event data */
|
||||
|
||||
@@ -44,6 +44,7 @@ const {
|
||||
getRuns,
|
||||
getRun,
|
||||
upsertRun,
|
||||
upsertRuns,
|
||||
deleteRun,
|
||||
deleteRunsForRundown,
|
||||
deleteAllRuns,
|
||||
@@ -140,6 +141,35 @@ describe('upsertRun() / getRun() / getRuns()', () => {
|
||||
});
|
||||
});
|
||||
|
||||
describe('upsertRuns()', () => {
|
||||
beforeEach(async () => {
|
||||
await loadReports('project-a');
|
||||
});
|
||||
|
||||
it('applies several runs in a single write', async () => {
|
||||
await upsertRuns([makeRun({ id: 'a' }), makeRun({ id: 'b' })]);
|
||||
|
||||
expect(getRuns().map((run) => run.id)).toEqual(['b', 'a']);
|
||||
const written = files.get(getPathToReports('project-a')) as { runs: ShowRun[] };
|
||||
expect(written.runs).toHaveLength(2);
|
||||
});
|
||||
|
||||
it('mixes inserts and replacements', async () => {
|
||||
await upsertRun(makeRun({ id: 'existing', label: 'before' }));
|
||||
await upsertRuns([makeRun({ id: 'existing', label: 'after' }), makeRun({ id: 'fresh' })]);
|
||||
|
||||
expect(getRuns()).toHaveLength(2);
|
||||
expect(getRun('existing')?.label).toBe('after');
|
||||
});
|
||||
|
||||
it('does not write when given nothing to do', async () => {
|
||||
await upsertRun(makeRun({ id: 'a' }));
|
||||
await upsertRuns([]);
|
||||
|
||||
expect(getRuns()).toHaveLength(1);
|
||||
});
|
||||
});
|
||||
|
||||
describe('deleteRun()', () => {
|
||||
beforeEach(async () => {
|
||||
await loadReports('project-a');
|
||||
|
||||
@@ -71,11 +71,26 @@ export function getRun(id: string): ShowRun | undefined {
|
||||
* Inserts or replaces a run, keeping the list ordered newest first
|
||||
*/
|
||||
export async function upsertRun(run: ShowRun): Promise<void> {
|
||||
const index = cache.runs.findIndex((candidate) => candidate.id === run.id);
|
||||
if (index === -1) {
|
||||
cache.runs.unshift(run);
|
||||
} else {
|
||||
cache.runs[index] = run;
|
||||
return upsertRuns([run]);
|
||||
}
|
||||
|
||||
/**
|
||||
* Inserts or replaces several runs in one pass.
|
||||
* Batching matters: these all live in a single file, so writing per run would
|
||||
* mean concurrent writes racing on the same path.
|
||||
*/
|
||||
export async function upsertRuns(updated: ShowRun[]): Promise<void> {
|
||||
if (updated.length === 0) {
|
||||
return;
|
||||
}
|
||||
|
||||
for (const run of updated) {
|
||||
const index = cache.runs.findIndex((candidate) => candidate.id === run.id);
|
||||
if (index === -1) {
|
||||
cache.runs.unshift(run);
|
||||
} else {
|
||||
cache.runs[index] = run;
|
||||
}
|
||||
}
|
||||
await persist();
|
||||
}
|
||||
|
||||
@@ -41,9 +41,17 @@ export type ShowRun = {
|
||||
* is renamed or deleted.
|
||||
*/
|
||||
rundownTitle: string;
|
||||
/** user editable, defaults to a formatted timestamp */
|
||||
/** user editable, defaults to a formatted local date and time */
|
||||
label: string;
|
||||
/**
|
||||
* Wall clock instant (milliseconds from epoch) the run began.
|
||||
* Not a time of day: runs must be datable and orderable across days.
|
||||
*/
|
||||
startedAt: number;
|
||||
/**
|
||||
* Time of day the last event in the run finished, or null while the run is
|
||||
* open. Only ever compared against the per event times in the same run.
|
||||
*/
|
||||
endedAt: MaybeNumber;
|
||||
report: OntimeReport;
|
||||
summary: RunSummary;
|
||||
|
||||
Reference in New Issue
Block a user