From 5ea3845f0d9fadcdbc189022971231b2cd76b524 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 8 Aug 2026 11:06:11 +0000 Subject: [PATCH] feat(automation): make a successful fire visible Every logger call in the automation module was a failure path, so a working automation and a misconfigured one looked identical: nothing happened either way, as far as the user could see. Two channels, because they answer different questions. A new AUTOMATION log origin says what happened and when. A coalesced socket message feeds a "last fired" column in the panel, which answers whether an automation is alive at all: one that stays blank while its neighbours tick is the clearest sign that a filter or a trigger is wrong. Flood control is the whole difficulty here. onClock fires every second and the logger queue holds 100 entries, so per-fire logging on a continuous lifecycle would evict everything else within two minutes. Those cycles log a single notice per load explaining the silence and nothing after; the rest dedupe inside a one second window so a rapid reload does not spam. The socket message still goes out for continuous cycles, throttled to once a second, because the panel needs it to show the automation is running. Log.tsx carried six copies of the same twelve line button. Adding a seventh origin was the moment to collapse them, so the next one is free. The client log store was also unbounded while the server queue is capped; it now holds 500 entries. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01LpbLJVVT26tzWkduck1M9H --- .../src/common/stores/automationFired.ts | 25 ++++ apps/client/src/common/stores/logger.ts | 8 +- apps/client/src/common/utils/socket.ts | 5 + .../AutomationSettingsForm.tsx | 9 +- .../AutomationsList.module.scss | 5 + .../automations-panel/AutomationsList.tsx | 54 +++++++- apps/client/src/features/log/Log.tsx | 130 +++++------------- .../__tests__/automation.service.test.ts | 100 +++++++++++++- .../api-data/automation/automation.service.ts | 77 ++++++++++- .../api-data/automation/automation.utils.ts | 18 +++ packages/types/src/api/websocket/data.type.ts | 14 +- .../src/definitions/runtime/Logger.type.ts | 1 + 12 files changed, 337 insertions(+), 109 deletions(-) create mode 100644 apps/client/src/common/stores/automationFired.ts diff --git a/apps/client/src/common/stores/automationFired.ts b/apps/client/src/common/stores/automationFired.ts new file mode 100644 index 000000000..bd14a722d --- /dev/null +++ b/apps/client/src/common/stores/automationFired.ts @@ -0,0 +1,25 @@ +import type { TimerLifeCycle } from 'ontime-types'; +import { useStore } from 'zustand'; +import { createStore } from 'zustand/vanilla'; + +type FiredRecord = { at: number; cycle: TimerLifeCycle }; + +type AutomationFiredStore = { + fired: Record; +}; + +/** + * Tracks when each automation last ran. + * Ephemeral by design: this is runtime feedback for the settings panel, not project data, + * and it is fed by a socket message the server already coalesces to once a second per automation + */ +const automationFired = createStore(() => ({ + fired: {}, +})); + +export const useAutomationFired = () => useStore(automationFired); + +export const addAutomationFired = (automationId: string, cycle: TimerLifeCycle) => + automationFired.setState((state) => ({ + fired: { ...state.fired, [automationId]: { at: Date.now(), cycle } }, + })); diff --git a/apps/client/src/common/stores/logger.ts b/apps/client/src/common/stores/logger.ts index 13d3b348e..254a646c8 100644 --- a/apps/client/src/common/stores/logger.ts +++ b/apps/client/src/common/stores/logger.ts @@ -17,9 +17,15 @@ const logger = createStore(() => ({ export const useLogData = () => useStore(logger); +/** + * The server queue is capped at 100 entries, the client's was not. + * A long show with chatty automations would otherwise grow this forever. + */ +const maxLogEntries = 500; + export const addLog = (log: Log) => logger.setState((state) => ({ - logs: [log, ...state.logs], + logs: [log, ...state.logs].slice(0, maxLogEntries), })); export const clearLogs = () => logger.setState({ logs: [] }); diff --git a/apps/client/src/common/utils/socket.ts b/apps/client/src/common/utils/socket.ts index a9366cc36..9df49bfd3 100644 --- a/apps/client/src/common/utils/socket.ts +++ b/apps/client/src/common/utils/socket.ts @@ -37,6 +37,7 @@ import { setClients, } from '../stores/clientStore'; import { addDialog } from '../stores/dialogStore'; +import { addAutomationFired } from '../stores/automationFired'; import { addLog } from '../stores/logger'; import { patchRuntime, patchRuntimeProperty } from '../stores/runtime'; @@ -173,6 +174,10 @@ export const connectSocket = () => { addLog(payload as Log); break; } + case MessageTag.AutomationFired: { + addAutomationFired(payload.automationId, payload.cycle); + break; + } case MessageTag.RuntimeData: { patchRuntime(payload); updateDevTools(payload); diff --git a/apps/client/src/features/app-settings/panel/automations-panel/AutomationSettingsForm.tsx b/apps/client/src/features/app-settings/panel/automations-panel/AutomationSettingsForm.tsx index 3ae8ed702..09f5019b3 100644 --- a/apps/client/src/features/app-settings/panel/automations-panel/AutomationSettingsForm.tsx +++ b/apps/client/src/features/app-settings/panel/automations-panel/AutomationSettingsForm.tsx @@ -12,6 +12,7 @@ import { preventEscape } from '../../../../common/utils/keyEvent'; import { isOnlyNumbers } from '../../../../common/utils/regex'; import { isOntimeCloud } from '../../../../externals'; import * as Panel from '../../panel-utils/PanelUtils'; +import useAppSettingsNavigation from '../../useAppSettingsNavigation'; const oscApiDocsUrl = 'https://docs.getontime.no/api/protocols/osc/'; @@ -32,6 +33,7 @@ export default function AutomationSettingsForm({ oscInputState, isLoading, }: AutomationSettingsProps) { + const { setLocation } = useAppSettingsNavigation(); const { handleSubmit, reset, @@ -97,7 +99,12 @@ export default function AutomationSettingsForm({ - An automation is what to send: OSC and HTTP messages, or an action inside Ontime. - A trigger is when to send it. Triggers for a single event live in the event editor. - OSC Input tells Ontime to listen to messages on the specific port. - See the docs + + See the docs + + diff --git a/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.module.scss b/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.module.scss index 3137d0529..8fcff2405 100644 --- a/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.module.scss +++ b/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.module.scss @@ -1,3 +1,8 @@ .muted { color: $muted-gray; } + +.lastFired { + font-size: $aux-text-size; + color: $green-400; +} diff --git a/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.tsx b/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.tsx index 2d90b2d87..89e1fc256 100644 --- a/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.tsx +++ b/apps/client/src/features/app-settings/panel/automations-panel/AutomationsList.tsx @@ -1,5 +1,5 @@ import { Automation, AutomationDTO, NormalisedAutomation, Trigger } from 'ontime-types'; -import { Fragment, useMemo, useState } from 'react'; +import { Fragment, useEffect, useMemo, useState } from 'react'; import { IoAdd, IoPencil, IoSparklesOutline, IoTrash } from 'react-icons/io5'; import { deleteAutomation } from '../../../../common/api/automation'; @@ -10,6 +10,7 @@ import Info from '../../../../common/components/info/Info'; import Tag from '../../../../common/components/tag/Tag'; import { getLifecycleLabel } from '../../../../common/constants/timerLifecycle'; import useAutomationSettings from '../../../../common/hooks-query/useAutomationSettings'; +import { useAutomationFired } from '../../../../common/stores/automationFired'; import { summariseOutputs } from '../../../../common/utils/automationOutputs'; import * as Panel from '../../panel-utils/PanelUtils'; import AutomationForm from './AutomationForm'; @@ -61,6 +62,7 @@ export default function AutomationsList({ automations, triggers, enabledAutomati }; const lifecyclesByAutomation = useMemo(() => groupTriggersByAutomation(triggers), [triggers]); + const { fired } = useAutomationFired(); const arrayAutomations = Object.keys(automations); @@ -105,10 +107,11 @@ export default function AutomationsList({ automations, triggers, enabledAutomati - Title - Runs on - Filter rule + Title + Runs on + Filter rule Sends + Last fired @@ -164,6 +167,9 @@ export default function AutomationsList({ automations, triggers, enabledAutomati )) )} + + + - + {deleteError} @@ -198,3 +204,41 @@ export default function AutomationsList({ automations, triggers, enabledAutomati ); } + +/** + * Shows how long ago an automation last ran. + * An automation that never ticks while its neighbours do is the clearest signal + * that something upstream of it, a filter or a trigger, is wrong + */ +function LastFired({ at }: { at?: number }) { + const [, setTick] = useState(0); + + useEffect(() => { + if (at === undefined) { + return; + } + const interval = setInterval(() => setTick((value) => value + 1), 1000); + return () => clearInterval(interval); + }, [at]); + + if (at === undefined) { + return —; + } + + return {formatElapsed(Date.now() - at)}; +} + +function formatElapsed(elapsed: number): string { + const seconds = Math.max(0, Math.floor(elapsed / 1000)); + if (seconds < 5) { + return 'just now'; + } + if (seconds < 60) { + return `${seconds}s ago`; + } + const minutes = Math.floor(seconds / 60); + if (minutes < 60) { + return `${minutes}m ago`; + } + return `${Math.floor(minutes / 60)}h ago`; +} diff --git a/apps/client/src/features/log/Log.tsx b/apps/client/src/features/log/Log.tsx index 43426b500..b5e5e24b4 100644 --- a/apps/client/src/features/log/Log.tsx +++ b/apps/client/src/features/log/Log.tsx @@ -9,118 +9,50 @@ import * as Panel from '../app-settings/panel-utils/PanelUtils'; import style from './Log.module.scss'; +const origins = Object.values(LogOrigin); + +type OriginFilters = Record; + +const allEnabled = Object.fromEntries(origins.map((origin) => [origin, true])) as OriginFilters; + export default function Log() { const { logs: logData } = useLogData(); const isExtracted = window.location.pathname.includes('/log'); - const [showClient, setShowClient] = useState(true); - const [showServer, setShowServer] = useState(true); - const [showRx, setShowRx] = useState(true); - const [showTx, setShowTx] = useState(true); - const [showPlayback, setShowPlayback] = useState(true); - const [showUser, setShowUser] = useState(true); + const [filters, setFilters] = useState(allEnabled); - const matchers: LogOrigin[] = []; - if (showUser) { - matchers.push(LogOrigin.User); - } - if (showClient) { - matchers.push(LogOrigin.Client); - } - if (showServer) { - matchers.push(LogOrigin.Server); - } - if (showRx) { - matchers.push(LogOrigin.Rx); - } - if (showTx) { - matchers.push(LogOrigin.Tx); - } - if (showPlayback) { - matchers.push(LogOrigin.Playback); - } + const filteredData = logData.filter((entry) => filters[entry.origin as LogOrigin]); - const filteredData = logData.filter((entry) => matchers.some((match) => entry.origin === match)); + const toggleOrigin = useCallback((origin: LogOrigin) => { + setFilters((prev) => ({ ...prev, [origin]: !prev[origin] })); + }, []); - const disableOthers = useCallback((toEnable: LogOrigin) => { - setShowUser(toEnable === LogOrigin.User); - setShowClient(toEnable === LogOrigin.Client); - setShowServer(toEnable === LogOrigin.Server); - setShowRx(toEnable === LogOrigin.Rx); - setShowTx(toEnable === LogOrigin.Tx); - setShowPlayback(toEnable === LogOrigin.Playback); + /** middle click solos an origin */ + const soloOrigin = useCallback((toEnable: LogOrigin) => { + setFilters(Object.fromEntries(origins.map((origin) => [origin, origin === toEnable])) as OriginFilters); }, []); return (
Filter by - - - - - - + {origins.map((origin) => { + const isEnabled = filters[origin]; + return ( + + ); + })} diff --git a/apps/server/src/api-data/automation/__tests__/automation.service.test.ts b/apps/server/src/api-data/automation/__tests__/automation.service.test.ts index 8ed92a9b9..3eb3d9221 100644 --- a/apps/server/src/api-data/automation/__tests__/automation.service.test.ts +++ b/apps/server/src/api-data/automation/__tests__/automation.service.test.ts @@ -1,10 +1,12 @@ import { PlayableEvent, TimerLifeCycle } from 'ontime-types'; +import { socket } from '../../../adapters/WebsocketAdapter.js'; +import { logger } from '../../../classes/Logger.js'; import { makeRuntimeStoreData } from '../../../stores/__mocks__/runtimeStore.mocks.js'; import { RuntimeState } from '../../../stores/runtimeState.js'; import { makeOntimeEvent } from '../../rundown/__mocks__/rundown.mocks.js'; import { addAutomation, addTrigger, deleteAllTriggers } from '../automation.dao.js'; -import { testConditions, triggerAutomations } from '../automation.service.js'; +import { resetAutomationLogState, testConditions, triggerAutomations } from '../automation.service.js'; import * as httpClient from '../clients/http.client.js'; import * as oscClient from '../clients/osc.client.js'; import { makeHTTPAction, makeOSCAction } from './testUtils.js'; @@ -644,3 +646,99 @@ describe('testConditions()', () => { }); }); }); + +/** + * A successful fire used to be invisible. Making it visible is only useful if the log + * stays readable: onClock fires every second and the logger queue holds 100 entries. + */ +describe('automation reporting', () => { + let logSpy = vi.spyOn(logger, 'info'); + let socketSpy = vi.spyOn(socket, 'sendAsJson'); + + beforeEach(async () => { + vi.spyOn(oscClient, 'emitOSC').mockImplementation(() => {}); + logSpy = vi.spyOn(logger, 'info').mockImplementation(() => {}); + socketSpy = vi.spyOn(socket, 'sendAsJson').mockImplementation(() => {}); + + await deleteAllTriggers(); + resetAutomationLogState(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + }); + + async function bind(title: string, cycle: TimerLifeCycle) { + const automation = await addAutomation({ + title, + filterRule: 'all', + filters: [], + outputs: [makeOSCAction()], + }); + await addTrigger({ title, trigger: cycle, automationId: automation.id }); + return automation; + } + + it('logs once per automation that fires, not once per output', async () => { + await bind('reporting-finish', TimerLifeCycle.onFinish); + logSpy.mockClear(); + + triggerAutomations(TimerLifeCycle.onFinish); + + expect(logSpy).toHaveBeenCalledTimes(1); + expect(logSpy.mock.calls[0][1]).toContain('reporting-finish'); + }); + + it('never logs per fire on a continuous lifecycle, and explains itself once', async () => { + await bind('reporting-clock', TimerLifeCycle.onClock); + logSpy.mockClear(); + + triggerAutomations(TimerLifeCycle.onClock); + triggerAutomations(TimerLifeCycle.onClock); + triggerAutomations(TimerLifeCycle.onClock); + + expect(logSpy).toHaveBeenCalledTimes(1); + expect(logSpy.mock.calls[0][1]).toContain('suppressed'); + }); + + it('shows the suppression notice again after a reload', async () => { + await bind('reporting-clock', TimerLifeCycle.onClock); + triggerAutomations(TimerLifeCycle.onClock); + logSpy.mockClear(); + + // onLoad bookends a run and resets the reporting state + triggerAutomations(TimerLifeCycle.onLoad); + triggerAutomations(TimerLifeCycle.onClock); + + expect(logSpy.mock.calls.some(([, message]) => String(message).includes('suppressed'))).toBe(true); + }); + + it('collapses repeats of the same automation and cycle inside the throttle window', async () => { + vi.useFakeTimers(); + await bind('reporting-danger', TimerLifeCycle.onDanger); + logSpy.mockClear(); + + triggerAutomations(TimerLifeCycle.onDanger); + triggerAutomations(TimerLifeCycle.onDanger); + expect(logSpy).toHaveBeenCalledTimes(1); + + vi.advanceTimersByTime(1001); + triggerAutomations(TimerLifeCycle.onDanger); + expect(logSpy).toHaveBeenCalledTimes(2); + }); + + it('reports a fire to the clients at most once a second, including on continuous lifecycles', async () => { + vi.useFakeTimers(); + await bind('reporting-clock', TimerLifeCycle.onClock); + socketSpy.mockClear(); + + triggerAutomations(TimerLifeCycle.onClock); + triggerAutomations(TimerLifeCycle.onClock); + expect(socketSpy).toHaveBeenCalledTimes(1); + + vi.advanceTimersByTime(1001); + triggerAutomations(TimerLifeCycle.onClock); + expect(socketSpy).toHaveBeenCalledTimes(2); + }); +}); diff --git a/apps/server/src/api-data/automation/automation.service.ts b/apps/server/src/api-data/automation/automation.service.ts index d2376bf5c..24bccb06b 100644 --- a/apps/server/src/api-data/automation/automation.service.ts +++ b/apps/server/src/api-data/automation/automation.service.ts @@ -1,8 +1,10 @@ import { + type Automation, type AutomationFilter, type AutomationOutput, type FilterRule, LogOrigin, + MessageTag, RuntimeStore, TimerLifeCycle, isHTTPOutput, @@ -11,19 +13,54 @@ import { } from 'ontime-types'; import { getPropertyFromPath } from 'ontime-utils'; +import { socket } from '../../adapters/WebsocketAdapter.js'; import { logger } from '../../classes/Logger.js'; import { isOntimeCloud } from '../../setup/environment.js'; import { eventStore } from '../../stores/EventStore.js'; import { getAutomationTriggers, getAutomations, getAutomationsEnabled } from './automation.dao.js'; -import { isContained, isEquivalent, isGreaterThan, isLessThan } from './automation.utils.js'; +import { isContained, isEquivalent, isGreaterThan, isLessThan, summariseOutputs } from './automation.utils.js'; import { emitHTTP } from './clients/http.client.js'; import { toOntimeAction } from './clients/ontime.client.js'; import { emitOSC } from './clients/osc.client.js'; +/** + * Lifecycles that fire continuously while the timer runs. + * The logger queue holds 100 entries, so logging every onClock fire would evict + * everything else within two minutes and make the log useless. + */ +const continuousCycles: TimerLifeCycle[] = [TimerLifeCycle.onClock, TimerLifeCycle.onUpdate]; + +/** floor between two reports about the same automation, in milliseconds */ +const reportThrottleMs = 1000; + +/** automations we have already warned about being bound to a continuous lifecycle */ +const suppressionNotices = new Set(); +/** last time we logged a given automation + cycle pair */ +const lastLoggedAt = new Map(); +/** last time we told the clients about a given automation */ +const lastReportedAt = new Map(); + +/** + * Clears the per-load logging state. + * Called when the runtime loads or stops so the suppression notice is shown again + * for the next show rather than once per server lifetime + */ +export function resetAutomationLogState() { + suppressionNotices.clear(); + lastLoggedAt.clear(); + lastReportedAt.clear(); +} + /** * Exposes a method for triggering actions based on a TimerLifeCycle event */ export function triggerAutomations(cycle: TimerLifeCycle) { + // a load or a stop bookends a run: start reporting from scratch so the next show + // gets its own suppression notice rather than inheriting one from the last + if (cycle === TimerLifeCycle.onLoad || cycle === TimerLifeCycle.onStop) { + resetAutomationLogState(); + } + if (!getAutomationsEnabled()) { return; } @@ -63,10 +100,48 @@ export function triggerAutomations(cycle: TimerLifeCycle) { const shouldSend = testConditions(automation.filters, automation.filterRule, store); if (shouldSend) { send(automation.outputs, store); + reportFired(trigger.automationId, automation, cycle); } }); } +/** + * Makes a successful automation visible, which it previously was not: + * the log answers what happened, the socket message answers whether an automation is alive + */ +function reportFired(automationId: string, automation: Automation, cycle: TimerLifeCycle) { + const now = Date.now(); + + // the panel shows a last fired time, so continuous lifecycles still report, but at most once a second + const lastReported = lastReportedAt.get(automationId); + if (lastReported === undefined || now - lastReported >= reportThrottleMs) { + lastReportedAt.set(automationId, now); + socket.sendAsJson(MessageTag.AutomationFired, { automationId, cycle }); + } + + if (continuousCycles.includes(cycle)) { + // one notice per load is enough to explain why the log goes quiet from here + if (!suppressionNotices.has(automationId)) { + suppressionNotices.add(automationId); + logger.info( + LogOrigin.Automation, + `${automation.title} is bound to ${cycle} and fires continuously, per-fire logging suppressed`, + ); + } + return; + } + + // a rapid reload can fire the same automation on the same cycle several times over + const logKey = `${automationId}:${cycle}`; + const lastLogged = lastLoggedAt.get(logKey); + if (lastLogged !== undefined && now - lastLogged < reportThrottleMs) { + return; + } + lastLoggedAt.set(logKey, now); + + logger.info(LogOrigin.Automation, `${automation.title} fired on ${cycle} → ${summariseOutputs(automation.outputs)}`); +} + /** * Exposes a method for bypassing the condition check and testing the sending of an output */ diff --git a/apps/server/src/api-data/automation/automation.utils.ts b/apps/server/src/api-data/automation/automation.utils.ts index 53546a044..fda5f63c0 100644 --- a/apps/server/src/api-data/automation/automation.utils.ts +++ b/apps/server/src/api-data/automation/automation.utils.ts @@ -1,4 +1,5 @@ import { + AutomationOutput, EntryId, FilterRule, MaybeNumber, @@ -25,6 +26,23 @@ export function isOntimeActionAction(value: string): value is OntimeAction['acti return ontimeActionKeyValues.includes(value); } +/** + * Describes what an automation sends, for the log line of a successful fire + * @example 'OSC ×2, HTTP' + */ +export function summariseOutputs(outputs: AutomationOutput[]): string { + const labels: Record = { osc: 'OSC', http: 'HTTP', ontime: 'Ontime action' }; + const counts = new Map(); + + for (const output of outputs) { + counts.set(output.type, (counts.get(output.type) ?? 0) + 1); + } + + return Array.from(counts.entries()) + .map(([type, count]) => (count > 1 ? `${labels[type]} ×${count}` : labels[type])) + .join(', '); +} + function toOscValue(argString: string): OscArgInput { const argAsNum = Number(argString); // NOTE: number like: 1 2.0 33333 diff --git a/packages/types/src/api/websocket/data.type.ts b/packages/types/src/api/websocket/data.type.ts index 3d09f2158..f42946e11 100644 --- a/packages/types/src/api/websocket/data.type.ts +++ b/packages/types/src/api/websocket/data.type.ts @@ -1,4 +1,5 @@ import type { Client } from '../../definitions/Clients.type.js'; +import type { TimerLifeCycle } from '../../definitions/core/TimerLifecycle.type.js'; import type { Log } from '../../definitions/runtime/Logger.type.js'; import type { RuntimeStore } from '../../definitions/runtime/RuntimeStore.type.js'; import type { MaybeNumber } from '../../utils/utils.type.js'; @@ -17,6 +18,7 @@ export enum MessageTag { Log = 'log', RuntimeData = 'runtime-data', Refetch = 'refetch', + AutomationFired = 'automation-fired', } // CLIENT TO SERVER @@ -36,6 +38,15 @@ type ListClientPacket = { }; type RuntimePacket = { tag: MessageTag.RuntimeData; payload: Partial }; +/** + * Reports that an automation ran, so clients can show it is alive. + * Coalesced server side: high frequency lifecycles do not send one of these per fire. + */ +type AutomationFiredPacket = { + tag: MessageTag.AutomationFired; + payload: { automationId: string; cycle: TimerLifeCycle }; +}; + type RefetchPacket = { tag: MessageTag.Refetch; payload: { @@ -58,4 +69,5 @@ export type WsPacketToClient = | LogPacket | ListClientPacket | RuntimePacket - | RefetchPacket; + | RefetchPacket + | AutomationFiredPacket; diff --git a/packages/types/src/definitions/runtime/Logger.type.ts b/packages/types/src/definitions/runtime/Logger.type.ts index 6fa7d3bb7..9dd130c49 100644 --- a/packages/types/src/definitions/runtime/Logger.type.ts +++ b/packages/types/src/definitions/runtime/Logger.type.ts @@ -19,6 +19,7 @@ export type LogMessage = { }; export enum LogOrigin { + Automation = 'AUTOMATION', Client = 'CLIENT', Playback = 'PLAYBACK', Rx = 'RX',