mirror of
https://github.com/cpvalente/ontime.git
synced 2026-08-21 15:09:10 +00:00
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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01LpbLJVVT26tzWkduck1M9H
This commit is contained in:
@@ -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<string, FiredRecord>;
|
||||||
|
};
|
||||||
|
|
||||||
|
/**
|
||||||
|
* 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<AutomationFiredStore>(() => ({
|
||||||
|
fired: {},
|
||||||
|
}));
|
||||||
|
|
||||||
|
export const useAutomationFired = () => useStore(automationFired);
|
||||||
|
|
||||||
|
export const addAutomationFired = (automationId: string, cycle: TimerLifeCycle) =>
|
||||||
|
automationFired.setState((state) => ({
|
||||||
|
fired: { ...state.fired, [automationId]: { at: Date.now(), cycle } },
|
||||||
|
}));
|
||||||
@@ -17,9 +17,15 @@ const logger = createStore<LogStore>(() => ({
|
|||||||
|
|
||||||
export const useLogData = () => useStore(logger);
|
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) =>
|
export const addLog = (log: Log) =>
|
||||||
logger.setState((state) => ({
|
logger.setState((state) => ({
|
||||||
logs: [log, ...state.logs],
|
logs: [log, ...state.logs].slice(0, maxLogEntries),
|
||||||
}));
|
}));
|
||||||
|
|
||||||
export const clearLogs = () => logger.setState({ logs: [] });
|
export const clearLogs = () => logger.setState({ logs: [] });
|
||||||
|
|||||||
@@ -37,6 +37,7 @@ import {
|
|||||||
setClients,
|
setClients,
|
||||||
} from '../stores/clientStore';
|
} from '../stores/clientStore';
|
||||||
import { addDialog } from '../stores/dialogStore';
|
import { addDialog } from '../stores/dialogStore';
|
||||||
|
import { addAutomationFired } from '../stores/automationFired';
|
||||||
import { addLog } from '../stores/logger';
|
import { addLog } from '../stores/logger';
|
||||||
import { patchRuntime, patchRuntimeProperty } from '../stores/runtime';
|
import { patchRuntime, patchRuntimeProperty } from '../stores/runtime';
|
||||||
|
|
||||||
@@ -173,6 +174,10 @@ export const connectSocket = () => {
|
|||||||
addLog(payload as Log);
|
addLog(payload as Log);
|
||||||
break;
|
break;
|
||||||
}
|
}
|
||||||
|
case MessageTag.AutomationFired: {
|
||||||
|
addAutomationFired(payload.automationId, payload.cycle);
|
||||||
|
break;
|
||||||
|
}
|
||||||
case MessageTag.RuntimeData: {
|
case MessageTag.RuntimeData: {
|
||||||
patchRuntime(payload);
|
patchRuntime(payload);
|
||||||
updateDevTools(payload);
|
updateDevTools(payload);
|
||||||
|
|||||||
+8
-1
@@ -12,6 +12,7 @@ import { preventEscape } from '../../../../common/utils/keyEvent';
|
|||||||
import { isOnlyNumbers } from '../../../../common/utils/regex';
|
import { isOnlyNumbers } from '../../../../common/utils/regex';
|
||||||
import { isOntimeCloud } from '../../../../externals';
|
import { isOntimeCloud } from '../../../../externals';
|
||||||
import * as Panel from '../../panel-utils/PanelUtils';
|
import * as Panel from '../../panel-utils/PanelUtils';
|
||||||
|
import useAppSettingsNavigation from '../../useAppSettingsNavigation';
|
||||||
|
|
||||||
const oscApiDocsUrl = 'https://docs.getontime.no/api/protocols/osc/';
|
const oscApiDocsUrl = 'https://docs.getontime.no/api/protocols/osc/';
|
||||||
|
|
||||||
@@ -32,6 +33,7 @@ export default function AutomationSettingsForm({
|
|||||||
oscInputState,
|
oscInputState,
|
||||||
isLoading,
|
isLoading,
|
||||||
}: AutomationSettingsProps) {
|
}: AutomationSettingsProps) {
|
||||||
|
const { setLocation } = useAppSettingsNavigation();
|
||||||
const {
|
const {
|
||||||
handleSubmit,
|
handleSubmit,
|
||||||
reset,
|
reset,
|
||||||
@@ -97,7 +99,12 @@ export default function AutomationSettingsForm({
|
|||||||
<span>- An automation is what to send: OSC and HTTP messages, or an action inside Ontime.</span>
|
<span>- An automation is what to send: OSC and HTTP messages, or an action inside Ontime.</span>
|
||||||
<span>- A trigger is when to send it. Triggers for a single event live in the event editor.</span>
|
<span>- A trigger is when to send it. Triggers for a single event live in the event editor.</span>
|
||||||
<span>- OSC Input tells Ontime to listen to messages on the specific port.</span>
|
<span>- OSC Input tells Ontime to listen to messages on the specific port.</span>
|
||||||
<ExternalLink href={oscApiDocsUrl}>See the docs</ExternalLink>
|
<Info.Footer>
|
||||||
|
<ExternalLink href={oscApiDocsUrl}>See the docs</ExternalLink>
|
||||||
|
<Button variant='ghosted' size='small' onClick={() => setLocation('network__log')}>
|
||||||
|
Automations report to the event log
|
||||||
|
</Button>
|
||||||
|
</Info.Footer>
|
||||||
</Info>
|
</Info>
|
||||||
</Panel.Section>
|
</Panel.Section>
|
||||||
|
|
||||||
|
|||||||
+5
@@ -1,3 +1,8 @@
|
|||||||
.muted {
|
.muted {
|
||||||
color: $muted-gray;
|
color: $muted-gray;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
.lastFired {
|
||||||
|
font-size: $aux-text-size;
|
||||||
|
color: $green-400;
|
||||||
|
}
|
||||||
|
|||||||
@@ -1,5 +1,5 @@
|
|||||||
import { Automation, AutomationDTO, NormalisedAutomation, Trigger } from 'ontime-types';
|
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 { IoAdd, IoPencil, IoSparklesOutline, IoTrash } from 'react-icons/io5';
|
||||||
|
|
||||||
import { deleteAutomation } from '../../../../common/api/automation';
|
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 Tag from '../../../../common/components/tag/Tag';
|
||||||
import { getLifecycleLabel } from '../../../../common/constants/timerLifecycle';
|
import { getLifecycleLabel } from '../../../../common/constants/timerLifecycle';
|
||||||
import useAutomationSettings from '../../../../common/hooks-query/useAutomationSettings';
|
import useAutomationSettings from '../../../../common/hooks-query/useAutomationSettings';
|
||||||
|
import { useAutomationFired } from '../../../../common/stores/automationFired';
|
||||||
import { summariseOutputs } from '../../../../common/utils/automationOutputs';
|
import { summariseOutputs } from '../../../../common/utils/automationOutputs';
|
||||||
import * as Panel from '../../panel-utils/PanelUtils';
|
import * as Panel from '../../panel-utils/PanelUtils';
|
||||||
import AutomationForm from './AutomationForm';
|
import AutomationForm from './AutomationForm';
|
||||||
@@ -61,6 +62,7 @@ export default function AutomationsList({ automations, triggers, enabledAutomati
|
|||||||
};
|
};
|
||||||
|
|
||||||
const lifecyclesByAutomation = useMemo(() => groupTriggersByAutomation(triggers), [triggers]);
|
const lifecyclesByAutomation = useMemo(() => groupTriggersByAutomation(triggers), [triggers]);
|
||||||
|
const { fired } = useAutomationFired();
|
||||||
|
|
||||||
const arrayAutomations = Object.keys(automations);
|
const arrayAutomations = Object.keys(automations);
|
||||||
|
|
||||||
@@ -105,10 +107,11 @@ export default function AutomationsList({ automations, triggers, enabledAutomati
|
|||||||
<Panel.Table>
|
<Panel.Table>
|
||||||
<thead>
|
<thead>
|
||||||
<tr>
|
<tr>
|
||||||
<th style={{ width: '35%' }}>Title</th>
|
<th style={{ width: '30%' }}>Title</th>
|
||||||
<th style={{ width: '25%' }}>Runs on</th>
|
<th style={{ width: '22%' }}>Runs on</th>
|
||||||
<th style={{ width: '15%' }}>Filter rule</th>
|
<th style={{ width: '13%' }}>Filter rule</th>
|
||||||
<th style={{ width: '15%' }}>Sends</th>
|
<th style={{ width: '15%' }}>Sends</th>
|
||||||
|
<th style={{ width: '12%' }}>Last fired</th>
|
||||||
<th />
|
<th />
|
||||||
</tr>
|
</tr>
|
||||||
</thead>
|
</thead>
|
||||||
@@ -164,6 +167,9 @@ export default function AutomationsList({ automations, triggers, enabledAutomati
|
|||||||
))
|
))
|
||||||
)}
|
)}
|
||||||
</Panel.InlineElements>
|
</Panel.InlineElements>
|
||||||
|
<td>
|
||||||
|
<LastFired at={fired[automationId]?.at} />
|
||||||
|
</td>
|
||||||
<Panel.InlineElements align='end' relation='inner' as='td'>
|
<Panel.InlineElements align='end' relation='inner' as='td'>
|
||||||
<IconButton
|
<IconButton
|
||||||
variant='ghosted-white'
|
variant='ghosted-white'
|
||||||
@@ -186,7 +192,7 @@ export default function AutomationsList({ automations, triggers, enabledAutomati
|
|||||||
})}
|
})}
|
||||||
{deleteError && (
|
{deleteError && (
|
||||||
<tr>
|
<tr>
|
||||||
<td colSpan={5}>
|
<td colSpan={6}>
|
||||||
<Panel.Error>{deleteError}</Panel.Error>
|
<Panel.Error>{deleteError}</Panel.Error>
|
||||||
</td>
|
</td>
|
||||||
</tr>
|
</tr>
|
||||||
@@ -198,3 +204,41 @@ export default function AutomationsList({ automations, triggers, enabledAutomati
|
|||||||
</Panel.Section>
|
</Panel.Section>
|
||||||
);
|
);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* 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 <span className={style.muted}>—</span>;
|
||||||
|
}
|
||||||
|
|
||||||
|
return <span className={style.lastFired}>{formatElapsed(Date.now() - at)}</span>;
|
||||||
|
}
|
||||||
|
|
||||||
|
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`;
|
||||||
|
}
|
||||||
|
|||||||
@@ -9,118 +9,50 @@ import * as Panel from '../app-settings/panel-utils/PanelUtils';
|
|||||||
|
|
||||||
import style from './Log.module.scss';
|
import style from './Log.module.scss';
|
||||||
|
|
||||||
|
const origins = Object.values(LogOrigin);
|
||||||
|
|
||||||
|
type OriginFilters = Record<LogOrigin, boolean>;
|
||||||
|
|
||||||
|
const allEnabled = Object.fromEntries(origins.map((origin) => [origin, true])) as OriginFilters;
|
||||||
|
|
||||||
export default function Log() {
|
export default function Log() {
|
||||||
const { logs: logData } = useLogData();
|
const { logs: logData } = useLogData();
|
||||||
const isExtracted = window.location.pathname.includes('/log');
|
const isExtracted = window.location.pathname.includes('/log');
|
||||||
|
|
||||||
const [showClient, setShowClient] = useState(true);
|
const [filters, setFilters] = useState<OriginFilters>(allEnabled);
|
||||||
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 matchers: LogOrigin[] = [];
|
const filteredData = logData.filter((entry) => filters[entry.origin as 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) => matchers.some((match) => entry.origin === match));
|
const toggleOrigin = useCallback((origin: LogOrigin) => {
|
||||||
|
setFilters((prev) => ({ ...prev, [origin]: !prev[origin] }));
|
||||||
|
}, []);
|
||||||
|
|
||||||
const disableOthers = useCallback((toEnable: LogOrigin) => {
|
/** middle click solos an origin */
|
||||||
setShowUser(toEnable === LogOrigin.User);
|
const soloOrigin = useCallback((toEnable: LogOrigin) => {
|
||||||
setShowClient(toEnable === LogOrigin.Client);
|
setFilters(Object.fromEntries(origins.map((origin) => [origin, origin === toEnable])) as OriginFilters);
|
||||||
setShowServer(toEnable === LogOrigin.Server);
|
|
||||||
setShowRx(toEnable === LogOrigin.Rx);
|
|
||||||
setShowTx(toEnable === LogOrigin.Tx);
|
|
||||||
setShowPlayback(toEnable === LogOrigin.Playback);
|
|
||||||
}, []);
|
}, []);
|
||||||
|
|
||||||
return (
|
return (
|
||||||
<div className={cx([style.container, isExtracted && style.extracted])}>
|
<div className={cx([style.container, isExtracted && style.extracted])}>
|
||||||
<Panel.InlineElements className={style.buttonBar}>
|
<Panel.InlineElements className={style.buttonBar}>
|
||||||
<span className={style.filterLabel}>Filter by</span>
|
<span className={style.filterLabel}>Filter by</span>
|
||||||
<Button
|
{origins.map((origin) => {
|
||||||
variant={showUser ? 'primary' : 'subtle'}
|
const isEnabled = filters[origin];
|
||||||
size='small'
|
return (
|
||||||
aria-pressed={showUser}
|
<Button
|
||||||
aria-label={`${showUser ? 'Hide' : 'Show'} ${LogOrigin.User} events`}
|
key={origin}
|
||||||
onClick={() => setShowUser((s) => !s)}
|
variant={isEnabled ? 'primary' : 'subtle'}
|
||||||
onAuxClick={() => disableOthers(LogOrigin.User)}
|
size='small'
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
aria-pressed={isEnabled}
|
||||||
>
|
aria-label={`${isEnabled ? 'Hide' : 'Show'} ${origin} events`}
|
||||||
{LogOrigin.User}
|
onClick={() => toggleOrigin(origin)}
|
||||||
</Button>
|
onAuxClick={() => soloOrigin(origin)}
|
||||||
<Button
|
onContextMenu={(e) => e.preventDefault()}
|
||||||
variant={showClient ? 'primary' : 'subtle'}
|
>
|
||||||
size='small'
|
{origin}
|
||||||
aria-pressed={showClient}
|
</Button>
|
||||||
aria-label={`${showClient ? 'Hide' : 'Show'} ${LogOrigin.Client} events`}
|
);
|
||||||
onClick={() => setShowClient((s) => !s)}
|
})}
|
||||||
onAuxClick={() => disableOthers(LogOrigin.Client)}
|
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
|
||||||
>
|
|
||||||
{LogOrigin.Client}
|
|
||||||
</Button>
|
|
||||||
<Button
|
|
||||||
variant={showServer ? 'primary' : 'subtle'}
|
|
||||||
size='small'
|
|
||||||
aria-pressed={showServer}
|
|
||||||
aria-label={`${showServer ? 'Hide' : 'Show'} ${LogOrigin.Server} events`}
|
|
||||||
onClick={() => setShowServer((s) => !s)}
|
|
||||||
onAuxClick={() => disableOthers(LogOrigin.Server)}
|
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
|
||||||
>
|
|
||||||
{LogOrigin.Server}
|
|
||||||
</Button>
|
|
||||||
<Button
|
|
||||||
variant={showPlayback ? 'primary' : 'subtle'}
|
|
||||||
size='small'
|
|
||||||
aria-pressed={showPlayback}
|
|
||||||
aria-label={`${showPlayback ? 'Hide' : 'Show'} ${LogOrigin.Playback} events`}
|
|
||||||
onClick={() => setShowPlayback((s) => !s)}
|
|
||||||
onAuxClick={() => disableOthers(LogOrigin.Playback)}
|
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
|
||||||
>
|
|
||||||
{LogOrigin.Playback}
|
|
||||||
</Button>
|
|
||||||
<Button
|
|
||||||
variant={showRx ? 'primary' : 'subtle'}
|
|
||||||
size='small'
|
|
||||||
aria-pressed={showRx}
|
|
||||||
aria-label={`${showRx ? 'Hide' : 'Show'} ${LogOrigin.Rx} events`}
|
|
||||||
onClick={() => setShowRx((s) => !s)}
|
|
||||||
onAuxClick={() => disableOthers(LogOrigin.Rx)}
|
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
|
||||||
>
|
|
||||||
{LogOrigin.Rx}
|
|
||||||
</Button>
|
|
||||||
<Button
|
|
||||||
variant={showTx ? 'primary' : 'subtle'}
|
|
||||||
size='small'
|
|
||||||
aria-pressed={showTx}
|
|
||||||
aria-label={`${showTx ? 'Hide' : 'Show'} ${LogOrigin.Tx} events`}
|
|
||||||
onClick={() => setShowTx((s) => !s)}
|
|
||||||
onAuxClick={() => disableOthers(LogOrigin.Tx)}
|
|
||||||
onContextMenu={(e) => e.preventDefault()}
|
|
||||||
>
|
|
||||||
{LogOrigin.Tx}
|
|
||||||
</Button>
|
|
||||||
<Button variant='subtle-destructive' size='small' onClick={clearLogs} className={style.apart}>
|
<Button variant='subtle-destructive' size='small' onClick={clearLogs} className={style.apart}>
|
||||||
<IoClose /> Clear
|
<IoClose /> Clear
|
||||||
</Button>
|
</Button>
|
||||||
|
|||||||
@@ -1,10 +1,12 @@
|
|||||||
import { PlayableEvent, TimerLifeCycle } from 'ontime-types';
|
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 { makeRuntimeStoreData } from '../../../stores/__mocks__/runtimeStore.mocks.js';
|
||||||
import { RuntimeState } from '../../../stores/runtimeState.js';
|
import { RuntimeState } from '../../../stores/runtimeState.js';
|
||||||
import { makeOntimeEvent } from '../../rundown/__mocks__/rundown.mocks.js';
|
import { makeOntimeEvent } from '../../rundown/__mocks__/rundown.mocks.js';
|
||||||
import { addAutomation, addTrigger, deleteAllTriggers } from '../automation.dao.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 httpClient from '../clients/http.client.js';
|
||||||
import * as oscClient from '../clients/osc.client.js';
|
import * as oscClient from '../clients/osc.client.js';
|
||||||
import { makeHTTPAction, makeOSCAction } from './testUtils.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);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
|||||||
@@ -1,8 +1,10 @@
|
|||||||
import {
|
import {
|
||||||
|
type Automation,
|
||||||
type AutomationFilter,
|
type AutomationFilter,
|
||||||
type AutomationOutput,
|
type AutomationOutput,
|
||||||
type FilterRule,
|
type FilterRule,
|
||||||
LogOrigin,
|
LogOrigin,
|
||||||
|
MessageTag,
|
||||||
RuntimeStore,
|
RuntimeStore,
|
||||||
TimerLifeCycle,
|
TimerLifeCycle,
|
||||||
isHTTPOutput,
|
isHTTPOutput,
|
||||||
@@ -11,19 +13,54 @@ import {
|
|||||||
} from 'ontime-types';
|
} from 'ontime-types';
|
||||||
import { getPropertyFromPath } from 'ontime-utils';
|
import { getPropertyFromPath } from 'ontime-utils';
|
||||||
|
|
||||||
|
import { socket } from '../../adapters/WebsocketAdapter.js';
|
||||||
import { logger } from '../../classes/Logger.js';
|
import { logger } from '../../classes/Logger.js';
|
||||||
import { isOntimeCloud } from '../../setup/environment.js';
|
import { isOntimeCloud } from '../../setup/environment.js';
|
||||||
import { eventStore } from '../../stores/EventStore.js';
|
import { eventStore } from '../../stores/EventStore.js';
|
||||||
import { getAutomationTriggers, getAutomations, getAutomationsEnabled } from './automation.dao.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 { emitHTTP } from './clients/http.client.js';
|
||||||
import { toOntimeAction } from './clients/ontime.client.js';
|
import { toOntimeAction } from './clients/ontime.client.js';
|
||||||
import { emitOSC } from './clients/osc.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<string>();
|
||||||
|
/** last time we logged a given automation + cycle pair */
|
||||||
|
const lastLoggedAt = new Map<string, number>();
|
||||||
|
/** last time we told the clients about a given automation */
|
||||||
|
const lastReportedAt = new Map<string, number>();
|
||||||
|
|
||||||
|
/**
|
||||||
|
* 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
|
* Exposes a method for triggering actions based on a TimerLifeCycle event
|
||||||
*/
|
*/
|
||||||
export function triggerAutomations(cycle: TimerLifeCycle) {
|
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()) {
|
if (!getAutomationsEnabled()) {
|
||||||
return;
|
return;
|
||||||
}
|
}
|
||||||
@@ -63,10 +100,48 @@ export function triggerAutomations(cycle: TimerLifeCycle) {
|
|||||||
const shouldSend = testConditions(automation.filters, automation.filterRule, store);
|
const shouldSend = testConditions(automation.filters, automation.filterRule, store);
|
||||||
if (shouldSend) {
|
if (shouldSend) {
|
||||||
send(automation.outputs, store);
|
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
|
* Exposes a method for bypassing the condition check and testing the sending of an output
|
||||||
*/
|
*/
|
||||||
|
|||||||
@@ -1,4 +1,5 @@
|
|||||||
import {
|
import {
|
||||||
|
AutomationOutput,
|
||||||
EntryId,
|
EntryId,
|
||||||
FilterRule,
|
FilterRule,
|
||||||
MaybeNumber,
|
MaybeNumber,
|
||||||
@@ -25,6 +26,23 @@ export function isOntimeActionAction(value: string): value is OntimeAction['acti
|
|||||||
return ontimeActionKeyValues.includes(value);
|
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<AutomationOutput['type'], string> = { osc: 'OSC', http: 'HTTP', ontime: 'Ontime action' };
|
||||||
|
const counts = new Map<AutomationOutput['type'], number>();
|
||||||
|
|
||||||
|
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 {
|
function toOscValue(argString: string): OscArgInput {
|
||||||
const argAsNum = Number(argString);
|
const argAsNum = Number(argString);
|
||||||
// NOTE: number like: 1 2.0 33333
|
// NOTE: number like: 1 2.0 33333
|
||||||
|
|||||||
@@ -1,4 +1,5 @@
|
|||||||
import type { Client } from '../../definitions/Clients.type.js';
|
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 { Log } from '../../definitions/runtime/Logger.type.js';
|
||||||
import type { RuntimeStore } from '../../definitions/runtime/RuntimeStore.type.js';
|
import type { RuntimeStore } from '../../definitions/runtime/RuntimeStore.type.js';
|
||||||
import type { MaybeNumber } from '../../utils/utils.type.js';
|
import type { MaybeNumber } from '../../utils/utils.type.js';
|
||||||
@@ -17,6 +18,7 @@ export enum MessageTag {
|
|||||||
Log = 'log',
|
Log = 'log',
|
||||||
RuntimeData = 'runtime-data',
|
RuntimeData = 'runtime-data',
|
||||||
Refetch = 'refetch',
|
Refetch = 'refetch',
|
||||||
|
AutomationFired = 'automation-fired',
|
||||||
}
|
}
|
||||||
|
|
||||||
// CLIENT TO SERVER
|
// CLIENT TO SERVER
|
||||||
@@ -36,6 +38,15 @@ type ListClientPacket = {
|
|||||||
};
|
};
|
||||||
type RuntimePacket = { tag: MessageTag.RuntimeData; payload: Partial<RuntimeStore> };
|
type RuntimePacket = { tag: MessageTag.RuntimeData; payload: Partial<RuntimeStore> };
|
||||||
|
|
||||||
|
/**
|
||||||
|
* 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 = {
|
type RefetchPacket = {
|
||||||
tag: MessageTag.Refetch;
|
tag: MessageTag.Refetch;
|
||||||
payload: {
|
payload: {
|
||||||
@@ -58,4 +69,5 @@ export type WsPacketToClient =
|
|||||||
| LogPacket
|
| LogPacket
|
||||||
| ListClientPacket
|
| ListClientPacket
|
||||||
| RuntimePacket
|
| RuntimePacket
|
||||||
| RefetchPacket;
|
| RefetchPacket
|
||||||
|
| AutomationFiredPacket;
|
||||||
|
|||||||
@@ -19,6 +19,7 @@ export type LogMessage = {
|
|||||||
};
|
};
|
||||||
|
|
||||||
export enum LogOrigin {
|
export enum LogOrigin {
|
||||||
|
Automation = 'AUTOMATION',
|
||||||
Client = 'CLIENT',
|
Client = 'CLIENT',
|
||||||
Playback = 'PLAYBACK',
|
Playback = 'PLAYBACK',
|
||||||
Rx = 'RX',
|
Rx = 'RX',
|
||||||
|
|||||||
Reference in New Issue
Block a user