Skip to content

Commit ff17642

Browse files
os-zhuangclaude
andauthored
fix(runtime): downgrade authored cron schedule envelope at the job boundary (#4567) (#4590)
`defineJob`'s parsed `schedule` carries the ADR expression envelope (`{dialect:'cron',source}`) while `IJobService.schedule` — and croner behind `CronJobAdapter` — take a bare cron string. AppPlugin passed the authored shape verbatim, croner threw "CronPattern: Pattern has to be of type string", and a per-job try/catch swallowed it into a warn: every declarative cron job was declared, built, booted and never scheduled. Convert at the single authoring→boundary seam (`toBoundaryJobSchedule`, called where retryPolicy/timeout are already threaded); the adapters stay strict. The failure path is now loud: error-level log with its own message, a boot summary line, and the new `job_schedule_failures_total` counter — no longer sharing the quiet warn used for "handler not found". Claude-Session: https://claude.ai/code/session_012C2cd7tL8QDoZ2QKN3djJ5 Co-authored-by: Claude <noreply@anthropic.com>
1 parent 6247d7f commit ff17642

9 files changed

Lines changed: 449 additions & 6 deletions

File tree

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
---
2+
"@objectstack/runtime": patch
3+
"@objectstack/observability": patch
4+
---
5+
6+
fix(runtime): declarative `defineJob` cron jobs are actually scheduled (#4567)
7+
8+
Every background job authored as `defineJob({ schedule: { type: 'cron', … } })`
9+
was **silently never scheduled**. `JobSchema.parse` rewrites the cron
10+
`expression` into the canonical expression envelope
11+
(`{ dialect: 'cron', source: '0 1 * * *' }` — the authoring/persistence tier),
12+
but `AppPlugin` handed `job.schedule` verbatim to `IJobService.schedule`, whose
13+
boundary contract documents `expression` as a **bare cron string** because
14+
`CronJobAdapter` passes it straight to croner. croner rejected the object
15+
(`CronPattern: Pattern has to be of type string.`), the throw was swallowed by a
16+
per-job `try/catch` that only `warn`ed, and the author saw a green build and a
17+
green boot with the job never running. `interval` / `once` schedules and
18+
flow `schedule` triggers were unaffected.
19+
20+
**Fix (contract-first).** The authoring→boundary downgrade now happens at the one
21+
place the two tiers meet — `AppPlugin`'s declarative-job registration, alongside
22+
the existing `retryPolicy` / `timeout` threading — via
23+
`toBoundaryJobSchedule()`. The adapters stay strict: no `typeof === 'object'`
24+
tolerance was added downstream, so the boundary keeps exactly one shape.
25+
A schedule that cannot be reduced to it (unknown type, AST-only or non-`cron`
26+
expression envelope, missing `intervalMs` / `at`) is rejected by name.
27+
28+
**The failure path is no longer silent.** A job that cannot be scheduled now logs
29+
at **error** level with its own message (`Background job FAILED TO SCHEDULE — it
30+
will never run`), plus a boot summary line when any job failed, and increments
31+
the new `job_schedule_failures_total` counter
32+
(`SEMCONV.jobScheduleFailuresTotal`, labels `app` / `job`) on the observability
33+
metrics registry. "Failed to schedule" no longer shares the quiet `warn` used by
34+
"handler not found in bundle.functions" — the first is an outage of declared
35+
work, the second is a job that was never going to run.
36+
37+
No authoring change is required: existing `defineJob` cron declarations start
38+
working on upgrade.

packages/observability/src/semconv.ts

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,15 @@ export const SEMCONV = {
4646
/** Counter, labels: `adapter`, `op`, `errorClass`. */
4747
cacheErrorsTotal: 'cache_errors_total',
4848

49+
// ── Background jobs — emitted by `@objectstack/runtime`'s AppPlugin ──
50+
/**
51+
* Counter, labels: `app`, `job`. Incremented when a DECLARED background
52+
* job could not be handed to the job service — i.e. the app booted green
53+
* but that job will never run (#4567). Any non-zero value is an outage of
54+
* the job, not a warning.
55+
*/
56+
jobScheduleFailuresTotal: 'job_schedule_failures_total',
57+
4958
// ── Package / registry-reader — emitted by `@objectstack/service-package` ──
5059
/** Counter, labels: `result` (`ok`|`miss`|`error`). */
5160
registryLookupsTotal: 'registry_lookups_total',

packages/runtime/package.json

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@
4747
"@objectstack/platform-objects": "workspace:*",
4848
"@objectstack/plugin-hono-server": "workspace:*",
4949
"@objectstack/service-datasource": "workspace:*",
50+
"@objectstack/service-job": "workspace:*",
5051
"@objectstack/service-messaging": "workspace:*",
5152
"typescript": "^6.0.3",
5253
"vitest": "^4.1.10"
Lines changed: 164 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,164 @@
1+
// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
4+
import type { PluginContext } from '@objectstack/core';
5+
import { defineJob } from '@objectstack/spec/system';
6+
import { InMemoryMetricsRegistry, OBSERVABILITY_METRICS_SERVICE, SEMCONV } from '@objectstack/observability';
7+
import { CronJobAdapter } from '@objectstack/service-job';
8+
import { AppPlugin } from './app-plugin.js';
9+
10+
/**
11+
* #4567 — declarative cron jobs must actually reach the scheduler.
12+
*
13+
* These run AppPlugin against the REAL `CronJobAdapter` (croner underneath),
14+
* not a recording double: the bug was that the authored schedule was rejected
15+
* *inside* the adapter and the throw was swallowed, so a double that records
16+
* whatever it is handed cannot see it.
17+
*/
18+
describe('AppPlugin — declarative background jobs (#4567)', () => {
19+
let adapter: CronJobAdapter;
20+
let metrics: InMemoryMetricsRegistry;
21+
let ctx: PluginContext;
22+
let readyHooks: Array<() => Promise<void>>;
23+
24+
beforeEach(() => {
25+
adapter = new CronJobAdapter();
26+
metrics = new InMemoryMetricsRegistry();
27+
readyHooks = [];
28+
ctx = {
29+
logger: { info: vi.fn(), error: vi.fn(), warn: vi.fn(), debug: vi.fn() },
30+
registerService: vi.fn(),
31+
getService: vi.fn((name: string) => {
32+
if (name === 'job') return adapter;
33+
if (name === OBSERVABILITY_METRICS_SERVICE) return metrics;
34+
if (name === 'objectql') return {};
35+
return undefined;
36+
}),
37+
getServices: vi.fn(() => []),
38+
hook: vi.fn((event: string, cb: () => Promise<void>) => {
39+
if (event === 'kernel:ready') readyHooks.push(cb);
40+
}),
41+
trigger: vi.fn(),
42+
} as unknown as PluginContext;
43+
});
44+
45+
afterEach(async () => {
46+
await adapter.destroy();
47+
});
48+
49+
const fireReady = async () => {
50+
for (const cb of readyHooks) await cb();
51+
};
52+
53+
const errorLogs = () => vi.mocked(ctx.logger.error).mock.calls.map(c => String(c[0]));
54+
const warnLogs = () => vi.mocked(ctx.logger.warn).mock.calls.map(c => String(c[0]));
55+
56+
it('schedules a defineJob cron job end-to-end — the adapter holds a live cron task', async () => {
57+
const sweep = vi.fn(async () => { /* handler body */ });
58+
const job = defineJob({
59+
name: 'health_sweep',
60+
schedule: { type: 'cron', expression: '0 1 * * *' },
61+
handler: 'sweep',
62+
});
63+
const plugin = new AppPlugin({
64+
id: 'com.test.jobs',
65+
jobs: [job],
66+
functions: { sweep },
67+
});
68+
69+
await plugin.start!(ctx);
70+
await fireReady();
71+
72+
// Scheduler state, not merely "did not throw": the adapter only records
73+
// a job after `new Cron(...)` succeeded.
74+
expect(await adapter.listJobs()).toContain('health_sweep');
75+
const task = (adapter as unknown as { jobs: Map<string, { task?: { nextRun(): Date | null } }> })
76+
.jobs.get('health_sweep')?.task;
77+
const next = task?.nextRun();
78+
expect(next).toBeInstanceOf(Date);
79+
// '0 1 * * *' with the schema-defaulted UTC timezone.
80+
expect(next!.getUTCHours()).toBe(1);
81+
expect(next!.getUTCMinutes()).toBe(0);
82+
83+
// And the registered task really runs the bundle handler.
84+
await adapter.trigger('health_sweep');
85+
expect(sweep).toHaveBeenCalledTimes(1);
86+
87+
expect(errorLogs()).toEqual([]);
88+
expect(metrics.totalCounter(SEMCONV.jobScheduleFailuresTotal)).toBe(0);
89+
});
90+
91+
it('REVERT-PROOF: the raw authored schedule still breaks the adapter, exactly as #4567 reported', async () => {
92+
const job = defineJob({
93+
name: 'health_sweep',
94+
schedule: { type: 'cron', expression: '0 1 * * *' },
95+
handler: 'sweep',
96+
});
97+
98+
// What AppPlugin used to pass verbatim. The adapter's contract is a bare
99+
// string and it stays strict — remove the downgrade in AppPlugin and the
100+
// end-to-end test above fails with precisely this croner error.
101+
await expect(
102+
adapter.schedule('health_sweep', job.schedule as never, async () => { /* noop */ }),
103+
).rejects.toThrow(/Pattern has to be of type string/i);
104+
expect(await adapter.listJobs()).not.toContain('health_sweep');
105+
});
106+
107+
it('interval jobs keep working (no envelope on that branch)', async () => {
108+
const plugin = new AppPlugin({
109+
id: 'com.test.jobs',
110+
jobs: [defineJob({ name: 'ping', schedule: { type: 'interval', intervalMs: 60_000 }, handler: 'h' })],
111+
functions: { h: vi.fn(async () => { /* noop */ }) },
112+
});
113+
114+
await plugin.start!(ctx);
115+
await fireReady();
116+
117+
expect(await adapter.listJobs()).toContain('ping');
118+
expect(errorLogs()).toEqual([]);
119+
});
120+
121+
it('a job that cannot be scheduled logs ERROR (not a silent warn) and counts', async () => {
122+
const plugin = new AppPlugin({
123+
id: 'com.test.jobs',
124+
jobs: [{
125+
name: 'bad_job',
126+
// A CEL envelope where a cron one belongs — unusable at the boundary.
127+
schedule: { type: 'cron', expression: { dialect: 'cel', source: 'now()' } },
128+
handler: 'h',
129+
enabled: true,
130+
}],
131+
functions: { h: vi.fn(async () => { /* noop */ }) },
132+
});
133+
134+
await plugin.start!(ctx);
135+
await fireReady();
136+
137+
expect(await adapter.listJobs()).not.toContain('bad_job');
138+
139+
// Loud: error level, its own distinct message, and a counter.
140+
const errors = errorLogs();
141+
expect(errors.some(m => m.includes('FAILED TO SCHEDULE'))).toBe(true);
142+
expect(errors.some(m => m.includes('declared but NOT scheduled'))).toBe(true);
143+
expect(vi.mocked(ctx.logger.error).mock.calls[0][2]).toMatchObject({ job: 'bad_job' });
144+
expect(metrics.totalCounter(SEMCONV.jobScheduleFailuresTotal, { job: 'bad_job' })).toBe(1);
145+
146+
// NOT folded into the warn stream that "handler missing"/"disabled" use.
147+
expect(warnLogs().some(m => /schedule/i.test(m))).toBe(false);
148+
});
149+
150+
it('a missing handler stays a warn — the two failures are not one signal', async () => {
151+
const plugin = new AppPlugin({
152+
id: 'com.test.jobs',
153+
jobs: [defineJob({ name: 'orphan', schedule: { type: 'cron', expression: '0 1 * * *' }, handler: 'nope' })],
154+
functions: {},
155+
});
156+
157+
await plugin.start!(ctx);
158+
await fireReady();
159+
160+
expect(warnLogs().some(m => m.includes('job handler not found'))).toBe(true);
161+
expect(errorLogs()).toEqual([]);
162+
expect(metrics.totalCounter(SEMCONV.jobScheduleFailuresTotal)).toBe(0);
163+
});
164+
});

packages/runtime/src/app-plugin.ts

Lines changed: 33 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,9 @@ import { readServiceSelfInfo } from '@objectstack/spec/api';
1313
import { QuickJSScriptRunner } from './sandbox/quickjs-runner.js';
1414
import { hookBodyRunnerFactory, actionBodyRunnerFactory } from './sandbox/body-runner.js';
1515
import { GLOBAL_ACTION_OBJECT_KEY } from './action-execution.js';
16-
import { countServerTiming } from '@objectstack/observability';
16+
import { toBoundaryJobSchedule } from './job-schedule.js';
17+
import { countServerTiming, SEMCONV } from '@objectstack/observability';
18+
import { resolveMetrics } from './observability/observability-service-plugin.js';
1719

1820
/**
1921
* The write options every seed insert must use — mirrors
@@ -810,7 +812,9 @@ export class AppPlugin implements Plugin {
810812
return;
811813
}
812814
const fnMap = collectBundleFunctions(this.bundle);
815+
const metrics = resolveMetrics(ctx);
813816
let ok = 0;
817+
let failed = 0;
814818
for (const job of jobs) {
815819
const jobName: string = job?.name;
816820
if (!jobName) {
@@ -831,7 +835,13 @@ export class AppPlugin implements Plugin {
831835
try {
832836
await svc.schedule(
833837
jobName,
834-
job.schedule,
838+
// #4567: authoring tier → boundary tier. `job.schedule`
839+
// is the PARSED `Schedule`, whose cron `expression` is
840+
// the ADR expression envelope `{dialect,source}`;
841+
// `IJobService.schedule` (and croner behind it) take a
842+
// bare cron string. Same seam, same place, as the
843+
// retryPolicy/timeout threading just below.
844+
toBoundaryJobSchedule(job.schedule, jobName),
835845
async (jobCtx: any) => {
836846
await handler({ ...jobCtx, jobId: jobName, bundle: this.bundle });
837847
},
@@ -842,12 +852,29 @@ export class AppPlugin implements Plugin {
842852
);
843853
ok++;
844854
} catch (err: any) {
845-
ctx.logger.warn('[AppPlugin] Failed to schedule job', {
846-
appId, job: jobName, error: err?.message ?? String(err),
847-
});
855+
failed++;
856+
// #4567: a job that fails to schedule is a SILENT OUTAGE —
857+
// the app builds and boots green while the work never runs.
858+
// It gets error level plus its own counter, and deliberately
859+
// NOT the `warn` that "handler not found" / "job disabled"
860+
// use: those describe a job that was never going to run,
861+
// this one describes a job the author is owed.
862+
ctx.logger.error(
863+
'[AppPlugin] Background job FAILED TO SCHEDULE — it will never run',
864+
err as Error,
865+
{ appId, job: jobName, schedule: job.schedule },
866+
);
867+
metrics.counter(SEMCONV.jobScheduleFailuresTotal, { app: appId, job: jobName });
848868
}
849869
}
850-
ctx.logger.info('[AppPlugin] Scheduled background jobs', { appId, count: ok });
870+
ctx.logger.info('[AppPlugin] Scheduled background jobs', { appId, count: ok, failed });
871+
if (failed > 0) {
872+
ctx.logger.error(
873+
'[AppPlugin] Some background jobs are declared but NOT scheduled',
874+
undefined,
875+
{ appId, scheduled: ok, failed },
876+
);
877+
}
851878
});
852879
}
853880
} catch (err: any) {
Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,94 @@
1+
// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
import { describe, it, expect } from 'vitest';
4+
import { defineJob } from '@objectstack/spec/system';
5+
import { toBoundaryJobSchedule } from './job-schedule.js';
6+
7+
/**
8+
* #4567 — the authoring↔boundary downgrade itself.
9+
*
10+
* `defineJob` parses the cron `expression` into the ADR expression envelope;
11+
* `IJobService.schedule` (and croner behind it) take a bare string. These pin
12+
* the one conversion that bridges them.
13+
*/
14+
describe('toBoundaryJobSchedule', () => {
15+
it('unwraps the cron expression envelope a parsed Schedule carries', () => {
16+
const job = defineJob({
17+
name: 'health_sweep',
18+
schedule: { type: 'cron', expression: '0 1 * * *' },
19+
handler: 'sweep',
20+
});
21+
22+
// The premise of #4567: parsing produced an envelope, not a string.
23+
expect(job.schedule).toEqual({
24+
type: 'cron',
25+
expression: { dialect: 'cron', source: '0 1 * * *' },
26+
timezone: 'UTC',
27+
});
28+
29+
expect(toBoundaryJobSchedule(job.schedule, 'health_sweep')).toEqual({
30+
type: 'cron',
31+
expression: '0 1 * * *',
32+
timezone: 'UTC',
33+
});
34+
});
35+
36+
it('accepts the authoring-input spelling (bare string) unchanged', () => {
37+
expect(toBoundaryJobSchedule({ type: 'cron', expression: '*/5 * * * *' }, 'j')).toEqual({
38+
type: 'cron',
39+
expression: '*/5 * * * *',
40+
});
41+
});
42+
43+
it('carries a string timezone across and drops a non-string one', () => {
44+
expect(
45+
toBoundaryJobSchedule(
46+
{ type: 'cron', expression: { dialect: 'cron', source: '0 2 * * *' }, timezone: 'America/New_York' },
47+
'j',
48+
),
49+
).toEqual({ type: 'cron', expression: '0 2 * * *', timezone: 'America/New_York' });
50+
51+
expect(
52+
toBoundaryJobSchedule({ type: 'cron', expression: '0 2 * * *', timezone: 42 as unknown as string }, 'j'),
53+
).toEqual({ type: 'cron', expression: '0 2 * * *' });
54+
});
55+
56+
it('passes interval / once schedules through (no envelope on those branches)', () => {
57+
const interval = defineJob({
58+
name: 'ping',
59+
schedule: { type: 'interval', intervalMs: 5000 },
60+
handler: 'h',
61+
});
62+
expect(toBoundaryJobSchedule(interval.schedule, 'ping')).toEqual({ type: 'interval', intervalMs: 5000 });
63+
64+
const once = defineJob({
65+
name: 'kickoff',
66+
schedule: { type: 'once', at: '2030-01-01T00:00:00.000Z' },
67+
handler: 'h',
68+
});
69+
expect(toBoundaryJobSchedule(once.schedule, 'kickoff')).toEqual({
70+
type: 'once',
71+
at: '2030-01-01T00:00:00.000Z',
72+
});
73+
});
74+
75+
it('throws — naming the job — on shapes that cannot reach the boundary', () => {
76+
// Wrong dialect: a CEL expression is not a schedule.
77+
expect(() =>
78+
toBoundaryJobSchedule({ type: 'cron', expression: { dialect: 'cel', source: 'now()' } }, 'bad_job'),
79+
).toThrow(/bad_job.*cel/s);
80+
81+
// AST-only envelope: nothing for croner to parse.
82+
expect(() =>
83+
toBoundaryJobSchedule({ type: 'cron', expression: { dialect: 'cron', ast: {} } }, 'bad_job'),
84+
).toThrow(/bad_job.*AST-only/s);
85+
86+
expect(() => toBoundaryJobSchedule({ type: 'cron' }, 'bad_job')).toThrow(/bad_job/);
87+
expect(() => toBoundaryJobSchedule({ type: 'cron', expression: ' ' }, 'bad_job')).toThrow(/bad_job/);
88+
expect(() => toBoundaryJobSchedule({ type: 'interval' }, 'bad_job')).toThrow(/bad_job.*intervalMs/s);
89+
expect(() => toBoundaryJobSchedule({ type: 'once' }, 'bad_job')).toThrow(/bad_job.*at/s);
90+
expect(() => toBoundaryJobSchedule({ type: 'weekly' }, 'bad_job')).toThrow(/bad_job.*weekly/s);
91+
expect(() => toBoundaryJobSchedule(undefined, 'bad_job')).toThrow(/bad_job/);
92+
expect(() => toBoundaryJobSchedule('0 1 * * *', 'bad_job')).toThrow(/bad_job/);
93+
});
94+
});

0 commit comments

Comments
 (0)