mirror of
https://github.com/THU-MAIC/OpenMAIC.git
synced 2026-10-02 01:15:18 +08:00
wyuc
64621adfa0
* feat(render-service): emit render and preview lifecycle events The service is silent apart from one startup banner, which leaves a deployment able to see *that* rendering happens — CPU, memory — but unable to answer how many renders succeeded, how long they took, or how long they waited for a slot. Three things compound to make the outcome of a render unobservable from outside the process: - Job state lives in `JobStore`, in memory by default, so every record is gone on restart. - A failed render is reported to the client as HTTP 200 whose *body* carries `status: 'failed'`, so any proxy, gateway or dashboard counting status codes sees a perfectly healthy service. - Nothing between admission and completion writes a line anywhere. This adds one JSON line per lifecycle transition on stdout, which every container log pipeline already collects: - `render_job_submitted` — with the queue and running depth at admission - `render_job_started` — with `queueWaitMs`, the time the job spent queued behind other renders. Nothing else exposes this today, and it is the signal that distinguishes "renders are slow" from "renders are waiting". - `render_job_finished` — with the outcome (succeeded / failed / cancelled), the total duration, and, for a failure, its machine-readable code - `render_admission_rejected` — with the reason a 429 was returned, on both `/render` and `/preview` - `preview_request` — status and duration for every response the synchronous preview route produces, emitted from middleware so 200, 413, 429, 504 and 500 are all covered without touching the handler's return paths Events carry only bounded, low-cardinality dimensions: an opaque job id, a state, a duration, a reason code. No client identity, no file or directory names, no scene content, and no raw error strings — a render works on untrusted, model-authored input, and none of it belongs in an operational log. A test asserts that a failure's free-text message, which can contain a scratch path, never reaches the log while its fixed-vocabulary code does. `RenderCoordinator` takes the sink through its existing options bag (`onEvent`), defaulting to the stdout emitter, so tests assert on events without going through the console. * fix(render-service): close the lifecycle for a job cancelled while queued Cancelling a job that has not started yet takes a different path from cancelling a running one: it updates the job store directly rather than going through `finishNonSuccess`. So it emitted no `render_job_finished` event — a submitted job was simply never heard from again, and any success rate computed from the event stream would have been quietly wrong. It also left the job's submission timestamp in the map, which is the one piece of per-job state these events keep. Both are fixed by closing the lifecycle in that branch too. The added test asserts a queued-then-cancelled job reports a terminal event, and fails without the fix. * fix(render-service): make the lifecycle stream summable and its fields honest An independent review of this branch found the event stream could not actually be summed into the rates it exists to produce, plus two tests that could not detect the regressions they were named for. All of these were demonstrated. - A job could emit `render_job_finished` twice. The success event was emitted before the terminal `jobs.update`, so a rejected write landed in the catch and closed the same job again as `failed` — one render counted as both a success and a failure. `JobStore` is a seam a Redis-backed store can fill, so a rejected terminal write is a real case, not a hypothetical. The success event now follows the last fallible await, and `finishEvent` is idempotent: it keys off the timing entry it consumes, so any second close is a no-op. - `durationMs` on a finished job was submission-to-finish while its doc claimed "time spent in the state the event closes", so p95 "render duration" tracked queue depth. It keeps that meaning, now documented, and the event also carries `queueWaitMs` and `renderMs` so a consumer can tell a slow render from a long queue without joining back to the started event. - `running` counts jobs from the moment they leave the queue, but the execution permit is shared with `/preview`, so a counted job may still be blocked. The field is documented as "admitted to run" rather than claiming to be a count of renders in flight. - `render_job_submitted` counted the submitting job in `queued`, so an idle service reported `queued: 1` and the obvious "alert when queued > 0" rule could never be written. It now excludes self, matching `render_job_started`. - `render_admission_rejected` and `preview_request` called the module-level emitter directly, so an embedder injecting a sink silently received three of five event types. `AppDeps` now takes the same `onEvent` seam. - The serializer walked `Object.entries(event)`. Excess-property checking made that safe for object literals but not for spreads, which are exempt — so the header's promise that no identity, path or content is ever logged rested on every future caller avoiding one. It now serializes an explicit field list. Tests: the route tests passed an `executionGate` that `AppDeps` does not have, silently discarded, and unnoticed because `tsconfig` includes only `src` so typecheck never sees `test/`. Removed, and they now assert through the injected sink instead of spying on the console. The leak test asserted only on event shape and still passed with the cleanup deleted; it now observes the tracked state through a `trackedJobs` accessor. Added regressions for the double close, the timing split and the queue depth — each verified to fail without its fix.
105 lines
3.0 KiB
TypeScript
105 lines
3.0 KiB
TypeScript
/**
|
|
* The event sink is the service's only operational output, so its shape is a
|
|
* contract: one JSON line, bounded dimensions only, and a level that lets a
|
|
* pipeline separate failures from routine transitions.
|
|
*/
|
|
import { afterEach, describe, expect, it, vi } from 'vitest';
|
|
import { emitRenderEvent } from '../src/events.js';
|
|
|
|
afterEach(() => {
|
|
vi.restoreAllMocks();
|
|
});
|
|
|
|
function captureStdout(): { lines: string[] } {
|
|
const lines: string[] = [];
|
|
vi.spyOn(console, 'log').mockImplementation((line: unknown) => {
|
|
lines.push(String(line));
|
|
});
|
|
return { lines };
|
|
}
|
|
|
|
describe('emitRenderEvent', () => {
|
|
it('writes one parseable JSON line carrying the event dimensions', () => {
|
|
const { lines } = captureStdout();
|
|
|
|
emitRenderEvent({
|
|
event: 'render_job_started',
|
|
jobId: 'job-1',
|
|
queueWaitMs: 1234,
|
|
queued: 2,
|
|
running: 1,
|
|
});
|
|
|
|
expect(lines).toHaveLength(1);
|
|
expect(lines[0]).not.toContain('\n');
|
|
const parsed = JSON.parse(lines[0]!);
|
|
expect(parsed).toMatchObject({
|
|
service: 'render-service',
|
|
component: 'render',
|
|
level: 'INFO',
|
|
event: 'render_job_started',
|
|
jobId: 'job-1',
|
|
queueWaitMs: 1234,
|
|
});
|
|
expect(typeof parsed.timestamp).toBe('string');
|
|
expect(parsed.message).toContain('1234ms');
|
|
});
|
|
|
|
it('omits absent dimensions rather than serializing nulls', () => {
|
|
const { lines } = captureStdout();
|
|
|
|
emitRenderEvent({ event: 'render_job_submitted', jobId: 'job-2' });
|
|
|
|
const parsed = JSON.parse(lines[0]!);
|
|
expect(parsed).not.toHaveProperty('queueWaitMs');
|
|
expect(parsed).not.toHaveProperty('outcome');
|
|
expect(parsed).not.toHaveProperty('errorCode');
|
|
expect(lines[0]).not.toContain('null');
|
|
});
|
|
|
|
it('reports a failed render at ERROR on stderr so stderr-only pipelines see it', () => {
|
|
const { lines } = captureStdout();
|
|
const errors: string[] = [];
|
|
vi.spyOn(console, 'error').mockImplementation((line: unknown) => {
|
|
errors.push(String(line));
|
|
});
|
|
|
|
emitRenderEvent({
|
|
event: 'render_job_finished',
|
|
jobId: 'job-3',
|
|
outcome: 'failed',
|
|
durationMs: 900,
|
|
errorCode: 'execution_failed',
|
|
});
|
|
|
|
expect(lines).toHaveLength(0);
|
|
expect(errors).toHaveLength(1);
|
|
expect(JSON.parse(errors[0]!)).toMatchObject({
|
|
level: 'ERROR',
|
|
outcome: 'failed',
|
|
errorCode: 'execution_failed',
|
|
});
|
|
});
|
|
|
|
it('keeps a cancelled render at INFO — it is an outcome, not a fault', () => {
|
|
const { lines } = captureStdout();
|
|
|
|
emitRenderEvent({ event: 'render_job_finished', jobId: 'job-4', outcome: 'cancelled' });
|
|
|
|
expect(JSON.parse(lines[0]!)).toMatchObject({ level: 'INFO', outcome: 'cancelled' });
|
|
});
|
|
|
|
it('labels the preview route with its own component', () => {
|
|
const { lines } = captureStdout();
|
|
|
|
emitRenderEvent({
|
|
event: 'preview_request',
|
|
route: '/preview',
|
|
status: 504,
|
|
durationMs: 20000,
|
|
});
|
|
|
|
expect(JSON.parse(lines[0]!)).toMatchObject({ component: 'preview', status: 504 });
|
|
});
|
|
});
|