Skip to content

Commit f127d4f

Browse files
authored
fix(policies): poll runs to completion with progress, soft-retry when queue is full (Stirling-Tools#6690)
## What & why Production reports of policy enforcement "hanging" traced to large/many-page documents: the watermark step's flatten-to-image (`convertPDFToImage`) on a 500+ page PDF takes minutes, exceeding both the client poll cap and the backend per-step timeout. This makes the slow case graceful instead of looking broken, and makes load-shedding non-fatal. ### Poll runs to completion (no false "hang") The client poll loop used a flat ~150s cap that was **shorter than the backend's 300s per-step timeout**, so it abandoned long-but-healthy runs mid-flight. The budget is now sized to the backend's real worst case — `stepCount × per-step timeout + grace`, learned from the first status report — so the client always polls long enough to surface the run's **actual** terminal state (success or the backend's real error) rather than a misleading client-side timeout. ### Per-step progress The activity feed now shows `Enforcing… · step n/m` (from `currentStep`/`stepCount`), so a slow step shows movement instead of a dead spinner. ### Soft-retry on queue rejection Under load the shared `JobQueue` rejects runs ("queue full"), which previously surfaced as a hard failure needing a manual Retry. The backend now tags that rejection with a stable `POLICY_QUEUE_FULL` errorCode; the client treats it as transient backpressure and **auto-retries the file in place** with exponential backoff (≈4s→64s, ~2 min), shown as a soft "Busy — retrying…" row, falling back to the manual Retry only once the retry budget is spent. ## Testing - **Frontend unit tests** (30 pass across the policies suite), including a new `usePolicyAutoRun.retry.test.tsx` that drives the real controller orchestration (poll → `POLICY_QUEUE_FULL` → relabel → backoff → in-place re-dispatch), plus poll-budget, step-progress, and activity-feed relabel cases. - **Backend** `PolicyEngineTest` case asserting a queue-rejected run carries the `POLICY_QUEUE_FULL` code. - Typecheck clean on all three flavors (proprietary/saas/core); prettier + spotless clean. - Poll-budget + progress + real-error surfacing were also verified live end-to-end against a 599-page run (survived past the old cap, showed step progress, reported the backend's real 300s-timeout failure, recovered after a simulated network drop). ## Not included (follow-ups) - The underlying flatten-to-image cost itself (bounded-memory/streaming flatten, revisiting `convertPDFToImage` default and the 300s timeout) — the real perf fix, deliberately out of scope here.
1 parent f33f4f8 commit f127d4f

9 files changed

Lines changed: 516 additions & 16 deletions

File tree

app/proprietary/src/main/java/stirling/software/proprietary/policy/engine/PolicyEngine.java

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,10 @@ public class PolicyEngine {
5959
// files. See ResourceMonitor#shouldQueueJob(int).
6060
private static final int RUN_RESOURCE_WEIGHT = 50;
6161

62+
// errorCode marking a run that was never admitted (job queue full under load). Transient: the
63+
// client treats it as "busy" and retries, rather than as a terminal processing failure.
64+
private static final String QUEUE_FULL_CODE = "POLICY_QUEUE_FULL";
65+
6266
private final PolicyExecutor stepExecutor;
6367
private final TaskManager taskManager;
6468
private final PolicyRunRegistry registry;
@@ -239,7 +243,8 @@ private ResponseEntity<?> failRejectedRun(
239243
if (!completion.isDone()) {
240244
String message = "Policy run could not be queued: " + ex.getMessage();
241245
log.error("Policy run {} was not admitted: {}", run.getRunId(), ex.getMessage());
242-
run.fail(message);
246+
// Transient admission rejection, not a processing failure (see QUEUE_FULL_CODE).
247+
run.failWithCode(message, QUEUE_FULL_CODE, null);
243248
taskManager.setError(run.getRunId(), message);
244249
completion.complete(run);
245250
}

app/proprietary/src/test/java/stirling/software/proprietary/policy/engine/PolicyEngineTest.java

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -336,6 +336,27 @@ void runIsQueuedUnderResourcePressure() {
336336
assertEquals(PolicyRunStatus.PENDING, registry.get(handle.runId()).getStatus());
337337
}
338338

339+
@Test
340+
void runRejectedWhenQueueFullCarriesTransientErrorCode() {
341+
when(resourceMonitor.shouldQueueJob(anyInt())).thenReturn(true);
342+
// Admission rejected (queue full): the queued future completes exceptionally.
343+
CompletableFuture<Object> rejected = new CompletableFuture<>();
344+
rejected.completeExceptionally(
345+
new RuntimeException("Job queue full, please try again later"));
346+
doReturn(rejected).when(jobQueue).queueJob(anyString(), anyInt(), any(), anyLong());
347+
348+
PolicyRunHandle handle =
349+
engine.submit(
350+
definition(new PipelineStep(ROTATE, Map.of())),
351+
PolicyInputs.of(List.of(pdf("input", "input.pdf"))),
352+
PolicyProgressListener.NOOP);
353+
354+
PolicyRun run = registry.get(handle.runId());
355+
assertEquals(PolicyRunStatus.FAILED, run.getStatus());
356+
// Tagged transient so the client backs off and retries instead of hard-failing.
357+
assertEquals("POLICY_QUEUE_FULL", run.getErrorCode());
358+
}
359+
339360
@Test
340361
void resumeIsNotYetImplemented() {
341362
assertThrows(UnsupportedOperationException.class, () -> engine.resume("any", List.of()));

frontend/editor/src/proprietary/components/policies/policyRunStore.test.ts

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,9 +1,11 @@
11
import { describe, it, expect, beforeEach } from "vitest";
22
import {
33
dispatchKey,
4+
getRun,
45
isDispatched,
56
markDispatched,
67
recordRunStart,
8+
removeRun,
79
updateRun,
810
resetPolicyRuns,
911
type PolicyRunRecord,
@@ -70,6 +72,16 @@ describe("policyRunStore", () => {
7072
expect(read("stirling-policy-runs").runs[0].status).toBe("PENDING");
7173
});
7274

75+
it("getRun returns the record by id, removeRun drops it but keeps the dispatched key", () => {
76+
recordRunStart(rec({ runId: "abc" }));
77+
expect(getRun("abc")?.fileId).toBe("f1");
78+
removeRun("abc");
79+
expect(getRun("abc")).toBeUndefined();
80+
expect(read("stirling-policy-runs").runs).toHaveLength(0);
81+
// The (policy, file) pair stays dispatched so the auto-run doesn't re-fire on its own.
82+
expect(isDispatched("security", "f1")).toBe(true);
83+
});
84+
7385
it("caps stored runs at 50, newest first", () => {
7486
for (let i = 0; i < 55; i++) {
7587
recordRunStart(rec({ runId: `r${i}`, fileId: `f${i}`, startedAt: i }));

frontend/editor/src/proprietary/components/policies/policyRunStore.ts

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,11 @@ export interface PolicyRunRecord {
1919
fileName: string;
2020
fileSize: number;
2121
status: PolicyRunStatus;
22+
/** Pipeline progress reported by the run-status endpoint: the 1-based step
23+
* currently running, and the total step count. Drive the "step X/Y" label
24+
* while a run is in flight. Absent until the first status report. */
25+
currentStep?: number;
26+
stepCount?: number;
2227
/** Output files (downloadable via /api/v1/general/files/{id}) once done. */
2328
outputs: { fileId: string; fileName: string }[];
2429
/** True once ALL outputs have been imported into the workspace. */
@@ -33,6 +38,9 @@ export interface PolicyRunRecord {
3338
error: string | null;
3439
/** Stable backend failure code (e.g. an entitlement sentinel) when FAILED; null otherwise. */
3540
errorCode?: string | null;
41+
/** Set while an auto-retry is pending after a transient (queue-full) rejection, so the activity
42+
* feed shows a soft "busy" row instead of a hard failure during the backoff window. */
43+
retrying?: boolean;
3644
/** Epoch ms when the run was dispatched. */
3745
startedAt: number;
3846
}
@@ -146,6 +154,19 @@ export function updateRun(runId: string, patch: Partial<PolicyRunRecord>) {
146154
emit();
147155
}
148156

157+
/** The current record for a run id, if any. */
158+
export function getRun(runId: string): PolicyRunRecord | undefined {
159+
return state.runs.find((r) => r.runId === runId);
160+
}
161+
162+
/** Drop a run record (leaving its dispatched key intact). Used when retrying a
163+
* queue-rejected run in place, so the replacement run doesn't stack a second row. */
164+
export function removeRun(runId: string) {
165+
if (!state.runs.some((r) => r.runId === runId)) return;
166+
state = { ...state, runs: state.runs.filter((r) => r.runId !== runId) };
167+
emit();
168+
}
169+
149170
/** Reset the store — used by tests to isolate it. */
150171
export function resetPolicyRuns() {
151172
state = { runs: [], dispatched: [] };
Lines changed: 106 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,106 @@
1+
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
2+
import { renderHook, act } from "@testing-library/react";
3+
4+
// The auto-run hook reaches into several contexts + the network; stub those so we can drive just
5+
// the queue-rejection retry path against the REAL run store.
6+
vi.mock("@app/constants/featureFlags", () => ({ POLICIES_ENABLED: true }));
7+
vi.mock("@app/contexts/FileContext", () => ({
8+
useAllFiles: () => ({ fileStubs: [] }),
9+
useFileManagement: () => ({ addFiles: vi.fn() }),
10+
useFileContext: () => ({ consumeFiles: vi.fn() }),
11+
}));
12+
vi.mock("@app/hooks/usePolicies", () => ({
13+
usePolicies: () => ({
14+
policies: {
15+
security: {
16+
configured: true,
17+
status: "active",
18+
backendId: "backend-1",
19+
runOn: "upload",
20+
},
21+
},
22+
}),
23+
}));
24+
vi.mock("@app/services/policyApi", () => ({
25+
runStoredPolicy: vi.fn(),
26+
getPolicyRun: vi.fn(),
27+
downloadPolicyOutput: vi.fn(),
28+
}));
29+
vi.mock("@app/services/fileStorage", () => ({
30+
fileStorage: { getStirlingFile: vi.fn() },
31+
}));
32+
33+
import { usePolicyAutoRun } from "@app/components/policies/usePolicyAutoRun";
34+
import {
35+
recordRunStart,
36+
getRun,
37+
resetPolicyRuns,
38+
usePolicyRuns,
39+
} from "@app/components/policies/policyRunStore";
40+
import { runStoredPolicy, getPolicyRun } from "@app/services/policyApi";
41+
import { fileStorage } from "@app/services/fileStorage";
42+
43+
const getRunApi = vi.mocked(getPolicyRun);
44+
const runStored = vi.mocked(runStoredPolicy);
45+
const getFile = vi.mocked(fileStorage.getStirlingFile);
46+
47+
const queueFullView = {
48+
runId: "run-1",
49+
status: "FAILED",
50+
currentStep: 0,
51+
stepCount: 2,
52+
error: "Policy run could not be queued: Job queue full",
53+
errorCode: "POLICY_QUEUE_FULL",
54+
outputs: [],
55+
} as never;
56+
57+
beforeEach(() => {
58+
vi.useFakeTimers();
59+
localStorage.clear();
60+
resetPolicyRuns();
61+
getRunApi.mockReset();
62+
runStored.mockReset();
63+
getFile.mockReset();
64+
});
65+
afterEach(() => vi.useRealTimers());
66+
67+
describe("auto-run queue-rejection retry", () => {
68+
it("relabels a queue-rejected run as retrying, then re-dispatches it in place", async () => {
69+
// The polled run comes back queue-rejected; the retry resolves the file + fires a fresh run.
70+
getRunApi.mockResolvedValue(queueFullView);
71+
getFile.mockResolvedValue({ size: 1234 } as never);
72+
runStored.mockResolvedValue("run-2");
73+
74+
recordRunStart({
75+
runId: "run-1",
76+
categoryId: "security",
77+
fileId: "file-1",
78+
fileName: "doc.pdf",
79+
fileSize: 1234,
80+
status: "RUNNING",
81+
outputs: [],
82+
error: null,
83+
startedAt: 0,
84+
});
85+
86+
renderHook(() => {
87+
usePolicyAutoRun();
88+
return usePolicyRuns();
89+
});
90+
91+
// First poll (2s cadence) sees the rejection → relabel as a soft "retrying" row.
92+
await act(async () => {
93+
await vi.advanceTimersByTimeAsync(2000);
94+
});
95+
expect(getRun("run-1")?.retrying).toBe(true);
96+
expect(runStored).not.toHaveBeenCalled();
97+
98+
// After the first backoff window (BASE 4s) the rejected record is dropped and a fresh run fires.
99+
await act(async () => {
100+
await vi.advanceTimersByTimeAsync(4000);
101+
});
102+
expect(runStored).toHaveBeenCalledWith("backend-1", [{ size: 1234 }]);
103+
expect(getRun("run-1")).toBeUndefined();
104+
expect(getRun("run-2")?.status).toBe("PENDING");
105+
});
106+
});
Lines changed: 160 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,160 @@
1+
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
2+
3+
// Mock the network + the run store so we can drive the poll loop deterministically.
4+
vi.mock("@app/services/policyApi", async (orig) => ({
5+
...(await orig<typeof import("@app/services/policyApi")>()),
6+
getPolicyRun: vi.fn(),
7+
}));
8+
vi.mock("@app/components/policies/policyRunStore", async (orig) => ({
9+
...(await orig<typeof import("@app/components/policies/policyRunStore")>()),
10+
updateRun: vi.fn(),
11+
}));
12+
13+
import { poll } from "@app/components/policies/usePolicyAutoRun";
14+
import { getPolicyRun } from "@app/services/policyApi";
15+
import { updateRun } from "@app/components/policies/policyRunStore";
16+
17+
const getRun = vi.mocked(getPolicyRun);
18+
const update = vi.mocked(updateRun);
19+
20+
const POLL_MS = 2000;
21+
// Must match the poll loop's budget formula (stepCount × per-step timeout + grace).
22+
// With the 2-step `view()` below that's 2 × 300_000 + 30_000 = 630_000ms.
23+
const STEP_TIMEOUT_MS = 300_000;
24+
const POLL_GRACE_MS = 30_000;
25+
const STEP_COUNT = 2;
26+
const BUDGET_MS = STEP_COUNT * STEP_TIMEOUT_MS + POLL_GRACE_MS;
27+
const view = (status: string) =>
28+
({
29+
runId: "r1",
30+
status,
31+
currentStep: 1,
32+
stepCount: STEP_COUNT,
33+
outputs: [],
34+
error: null,
35+
}) as never;
36+
37+
beforeEach(() => {
38+
vi.useFakeTimers();
39+
getRun.mockReset();
40+
update.mockReset();
41+
});
42+
afterEach(() => vi.useRealTimers());
43+
44+
/** Run the poll loop for n cadence ticks, flushing the awaited fetch each tick. */
45+
async function tick(n: number) {
46+
for (let i = 0; i < n; i++) await vi.advanceTimersByTimeAsync(POLL_MS);
47+
}
48+
49+
describe("policy run poll loop", () => {
50+
it("stops and marks FAILED after repeated run-not-found (404)", async () => {
51+
getRun.mockRejectedValue({ code: "ERR_NOT_FOUND" });
52+
const p = poll("r1");
53+
await tick(3); // MAX_NOT_FOUND consecutive 404s
54+
await p;
55+
expect(update).toHaveBeenCalledWith(
56+
"r1",
57+
expect.objectContaining({ status: "FAILED" }),
58+
);
59+
// It gave up after the not-found streak, not after the full time budget.
60+
expect(getRun.mock.calls.length).toBe(3);
61+
});
62+
63+
it("also detects 404 via axios-style response.status", async () => {
64+
getRun.mockRejectedValue({ response: { status: 404 } });
65+
const p = poll("r1");
66+
await tick(3);
67+
await p;
68+
expect(update).toHaveBeenCalledWith(
69+
"r1",
70+
expect.objectContaining({ status: "FAILED" }),
71+
);
72+
});
73+
74+
it("does NOT fail on a brief not-found blip that then recovers", async () => {
75+
getRun
76+
.mockRejectedValueOnce({ code: "ERR_NOT_FOUND" })
77+
.mockResolvedValue(view("COMPLETED"));
78+
const p = poll("r1");
79+
await tick(2);
80+
await p;
81+
const statuses = update.mock.calls.map(
82+
(c) => (c[1] as { status: string }).status,
83+
);
84+
expect(statuses).toContain("COMPLETED");
85+
expect(statuses).not.toContain("FAILED");
86+
});
87+
88+
it("transient non-404 errors don't count toward the not-found streak", async () => {
89+
getRun
90+
.mockRejectedValueOnce({ code: "ERR_NOT_FOUND" })
91+
.mockRejectedValueOnce({ response: { status: 500 } })
92+
.mockRejectedValueOnce({ code: "ERR_NOT_FOUND" })
93+
.mockResolvedValue(view("COMPLETED"));
94+
const p = poll("r1");
95+
await tick(4);
96+
await p;
97+
const statuses = update.mock.calls.map(
98+
(c) => (c[1] as { status: string }).status,
99+
);
100+
expect(statuses).toContain("COMPLETED");
101+
expect(statuses).not.toContain("FAILED");
102+
});
103+
104+
it("marks FAILED when the run never reaches a terminal state within the budget", async () => {
105+
getRun.mockResolvedValue(view("RUNNING"));
106+
const p = poll("r1");
107+
// Advance past the full step-count-derived budget in one go.
108+
await vi.advanceTimersByTimeAsync(BUDGET_MS + POLL_MS);
109+
await p;
110+
expect(update).toHaveBeenLastCalledWith(
111+
"r1",
112+
expect.objectContaining({ status: "FAILED" }),
113+
);
114+
});
115+
116+
it("keeps polling a long run for the whole step budget (no premature giveup)", async () => {
117+
getRun.mockResolvedValue(view("RUNNING"));
118+
const p = poll("r1");
119+
// 200s in: a single step may run up to the per-step timeout, so the run is
120+
// still legitimately in flight and must keep being polled, not failed.
121+
await tick(100);
122+
expect(update).not.toHaveBeenCalledWith(
123+
"r1",
124+
expect.objectContaining({ status: "FAILED" }),
125+
);
126+
// Let it run out so the dangling promise doesn't leak into other tests.
127+
await vi.advanceTimersByTimeAsync(BUDGET_MS);
128+
await p;
129+
});
130+
131+
it("records pipeline progress (currentStep/stepCount) while running", async () => {
132+
getRun
133+
.mockResolvedValueOnce(view("RUNNING"))
134+
.mockResolvedValue(view("COMPLETED"));
135+
const p = poll("r1");
136+
await tick(2);
137+
await p;
138+
expect(update).toHaveBeenCalledWith(
139+
"r1",
140+
expect.objectContaining({ currentStep: 1, stepCount: STEP_COUNT }),
141+
);
142+
});
143+
144+
it("finishes cleanly on a terminal status and fires onTerminal", async () => {
145+
getRun.mockResolvedValue(view("COMPLETED"));
146+
const onTerminal = vi.fn();
147+
const p = poll("r1", onTerminal);
148+
await tick(1);
149+
await p;
150+
expect(update).toHaveBeenCalledWith(
151+
"r1",
152+
expect.objectContaining({ status: "COMPLETED" }),
153+
);
154+
expect(onTerminal).toHaveBeenCalledTimes(1);
155+
expect(update).not.toHaveBeenCalledWith(
156+
"r1",
157+
expect.objectContaining({ status: "FAILED" }),
158+
);
159+
});
160+
});

0 commit comments

Comments
 (0)