LibreChat/api/server/controllers/agents/callbacks.background.spec.js
Danny Avila fb8ae881cf
⏱️ feat: Show Run-Step Durations On Tool Cards (#14892)
* ⏱️ feat: Show Run-Step Durations On Tool Cards

Surfaces how long each tool call took, derived from the `closed_at` /
`created_at` pair already carried by `on_run_step_closed` — the same event
#14871 and #14873 use for the terminal status. No new event, no new SDK
surface.

The duration is stamped onto the content part at the same three sites as
`runStepStatus`, so it survives a reload and a resumable reconnect rather
than living only on the live React message:

- `callbacks.js`, on the aggregated part before the event is forwarded
- `RedisJobStore`, in the host-authored replay reconstruction branch
- `useStepHandler`, on the live message

Rendering lands in the shared `ProgressText`, which nine tool cards already
use, rather than in each card: one place decides whether a duration is shown
and how it reads, and the cards only forward the number. That keeps this from
adding a tenth independent state derivation to a component family whose
label/announcement/progress split is already the subject of AI-1810.

The value is deliberately absent rather than zero whenever it would be a
guess — no `created_at`, non-finite input, or a negative elapsed time from
two clocks that disagree, which is now reachable because a step can be opened
in one process and closed in another after a checkpoint resume. Sub-second
durations are suppressed as noise, and it renders only on a settled,
non-error card, where the slot is not already carrying the cancelled icon or
the error suffix.

For assistive technology the compact form (`3.5s`) is hidden and paired with
a spoken equivalent ("took 3.5 seconds"), both inside the button, so the
accessible name carries the duration without an `aria-live` region
re-announcing it.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🎨 style: Sort Imports In Touched Files

The import-sort gate runs against the files a PR changes, so pre-existing
drift in `ProgressText.tsx` and `RedisJobStore.ts` surfaced on this branch.
Both were already unsorted on `dev`; this is the sorter's output, with no
semantic change.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🐛 fix: Accept Partial Timestamps In Run-Step Duration Helper

`getReportableRunStepDurationMs` declared its parameter as
`Pick<RunStepClosedEvent, 'created_at' | 'closed_at'>`, where `closed_at` is
required. That contradicted the function's own purpose: every guard inside it
exists precisely to handle stamps that may be missing.

The Redis replay branch reconstructs closures from persisted JSON and holds
nothing stronger than "might be a number", so it failed to typecheck against
the narrower signature.

Widened to an exported `RunStepTimestamps` shape with both stamps optional,
rather than asserting at the call site — an assertion would move the decision
about what is trustworthy somewhere it cannot be enforced, which is the thing
the helper exists to centralize. Callers holding a fully-typed event still
pass, since a required field satisfies an optional one.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🐛 fix: Suppress Duration When Failure Arrives As errorSuffix Alone

At every call site `error` carries cancellation while failure travels
through `errorSuffix` with `error` false, so gating the duration on
`!error` alone rendered "· 3.5s" beside "· failed" — and announced it.
The gate now checks both terminal-failure channels.

The original test pinned only the `error: true` path, which is why this
survived; the failed-via-suffix path is now pinned separately, both the
visible and the announced half.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🧩 refactor: Persist Raw Run-Step Durations, Threshold At Render Only

The three stamp sites filtered through the 1-second reportability
threshold before persisting, baking a presentation rule into stored
data: a 900ms step stored nothing, making "fast" indistinguishable from
"not derivable" and unrecoverable if the display rule ever changes.

Stamp sites now persist the raw `getRunStepDurationMs` value — absent
only when genuinely not derivable — and the renderer alone decides what
is worth showing, which `ProgressText` already did. Rendering is
unchanged. `getReportableRunStepDurationMs` is removed; it existed only
to serve the write-time filter, and a test now pins that sub-threshold
durations survive to storage.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🐛 fix: Suppress Duration On Backgrounded Bash And Code Cards

A backgrounded call's run step closes when dispatch returns the handle,
so the stamped duration is the dispatch time. Rendering it beside
"Running/Finished in background" misstated a detached task's runtime as
seconds — and violated the "settled card only" rule, since the card is
still tracking the detached run. Scope is exactly the two cards that
parse background handles.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🌍 fix: Format The Sub-10s Decimal For The Active Locale

The fractional seconds value was interpolated as a raw JS number, which
hardcodes the en-US decimal point into every language — "1.4s" where
the locale writes "1,4 s" — and translators cannot fix a number
formatted in code. The value is now formatted via Intl.NumberFormat
with i18n.language, following MessageTimestamp's pattern of threading
the language into the util; plural-key selection stays on the numeric
value. A malformed language tag falls back to the plain number.

Also documents the two accepted limits of the derivation, so they read
as decisions rather than oversights: positive clock skew is
undetectable from a single stamp pair, and the value is wall-clock
elapsed, so a step held open across a suspension (checkpoint resume,
HITL approval wait) includes that time.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🐛 fix: Persist A Durable `backgrounded` Marker Through Harvest; Localize Minute Digits

Codex round 3, both findings confirmed.

**Background origin survived only as transient state.** The dispatch
handle in `tool_call.output` and the live status-marker attachment are
both gone once the harvester patches the settled task's stdout over the
handle — so the round-2 suppression (`backgroundHandle == null`) came
back on after harvest or reload, showing dispatch time as the task's
runtime. Following the same rule as e4bd15d (persist facts, decide at
render): the harvest patch now stamps `backgrounded: true` onto the
tool call in the same atomic write that erases the handle — on the heal
path too, which re-applies over full-row saves that reverted the part.
The cards gate on handle-or-marker; the dispatch duration itself stays
stored.

**Minute-branch digits bypassed locale formatting.** The seconds branch
went through Intl.NumberFormat while minutes interpolated raw numbers,
so Arabic/Persian locales flipped to ASCII digits above one minute. All
interpolated values now flow through the (renamed) formatDurationValue;
an ar-EG test pins the localized digits.

data-schemas cannot be installed in this environment (same npm ci 403 as
packages/api), so message.ts/harvest.ts are syntax-checked with
resolution off and otherwise verified by review; CI runs their real
typecheck and suites.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🧪 test: Assert The `markBackgrounded` Stamp In Harvest Expectations

The successful-harvest test's exact `toHaveBeenCalledWith` object did
not include the newly forwarded `markBackgrounded`, so the API suite
would fail on it. All three harvest-call expectations now assert
`markBackgrounded: true` — the exact-object one of necessity, the two
`objectContaining` ones deliberately, since the durable stamp (on the
best-effort file-failure path and the reapply heal alike) is now part
of the behavior under test.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

* 🎨 style: Wrap Harvest Spec Expectation Per Prettier

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014vLhxCFMYkCaTsoFTiAjJ5

---------

Co-authored-by: Claude <noreply@anthropic.com>
2026-08-16 16:17:02 -04:00

202 lines
7.3 KiB
JavaScript

jest.mock('~/server/services/Files/Code/process', () => ({
processCodeOutput: jest.fn(),
runPreviewFinalize: jest.fn(),
}));
jest.mock('~/server/services/Files/Citations', () => ({ processFileCitations: jest.fn() }));
jest.mock('~/server/services/Files/process', () => ({ saveBase64Image: jest.fn() }));
const { processCodeOutput, runPreviewFinalize } = require('~/server/services/Files/Code/process');
const { createBackgroundCodeResultHandler } = require('./callbacks');
const req = { user: { id: 'user-1' } };
const baseParams = {
toolName: 'execute_code',
toolCallId: 'call_code',
messageId: 'msg-dispatch',
conversationId: 'convo-1',
agentId: 'agent_a',
output: 'stdout:\nhello',
artifact: {
session_id: 'exec-sess',
files: [
{ id: 'f1', name: 'plot.png', storage_session_id: 'store-1' },
{ id: 'f2', name: 'input.csv', inherited: true },
],
},
};
describe('createBackgroundCodeResultHandler', () => {
beforeEach(() => {
jest.clearAllMocks();
});
it('persists non-inherited files with the original identity and patches the message row', async () => {
processCodeOutput.mockResolvedValue({
file: { file_id: 'f1', filename: 'plot.png', toolCallId: 'call_code' },
finalize: undefined,
});
const updateToolCallResult = jest.fn().mockResolvedValue({ matched: true, unfinished: false });
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
const result = await handler(baseParams);
expect(processCodeOutput).toHaveBeenCalledTimes(1);
expect(processCodeOutput).toHaveBeenCalledWith(
expect.objectContaining({
req,
id: 'f1',
name: 'plot.png',
messageId: 'msg-dispatch',
toolCallId: 'call_code',
conversationId: 'convo-1',
agentId: 'agent_a',
session_id: 'store-1',
freshClaimAfter: expect.any(Number),
}),
);
expect(updateToolCallResult).toHaveBeenCalledTimes(1);
expect(updateToolCallResult).toHaveBeenCalledWith({
userId: 'user-1',
messageId: 'msg-dispatch',
conversationId: 'convo-1',
toolCallId: 'call_code',
agentId: 'agent_a',
output: 'stdout:\nhello',
attachments: [{ file_id: 'f1', filename: 'plot.png', toolCallId: 'call_code' }],
markBackgrounded: true,
});
expect(result).toEqual({
attachments: [{ file_id: 'f1', filename: 'plot.png', toolCallId: 'call_code' }],
});
});
it('anchors the stale-output guard to dispatch time when provided', async () => {
processCodeOutput.mockResolvedValue({ file: { file_id: 'f1' } });
const handler = createBackgroundCodeResultHandler({
req,
updateToolCallResult: jest.fn().mockResolvedValue({ matched: true, unfinished: false }),
});
await handler({ ...baseParams, dispatchedAt: 12345 });
expect(processCodeOutput).toHaveBeenCalledWith(
expect.objectContaining({ freshClaimAfter: 12345 }),
);
});
it('runs deferred preview finalization without a live stream callback', async () => {
const finalize = jest.fn();
processCodeOutput.mockResolvedValue({
file: { file_id: 'f1' },
finalize,
previewRevision: 3,
});
const handler = createBackgroundCodeResultHandler({
req,
updateToolCallResult: jest.fn().mockResolvedValue({ matched: true, unfinished: false }),
});
await handler(baseParams);
expect(runPreviewFinalize).toHaveBeenCalledWith({ finalize, fileId: 'f1', previewRevision: 3 });
});
it('retries the row patch until the dispatch turn persists', async () => {
jest.useFakeTimers();
try {
processCodeOutput.mockResolvedValue({ file: { file_id: 'f1' } });
const updateToolCallResult = jest
.fn()
.mockResolvedValueOnce({ matched: false, unfinished: false })
.mockResolvedValueOnce({ matched: false, unfinished: false })
.mockResolvedValue({ matched: true, unfinished: false });
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
const promise = handler(baseParams);
await jest.advanceTimersByTimeAsync(250);
await jest.advanceTimersByTimeAsync(500);
const result = await promise;
expect(updateToolCallResult).toHaveBeenCalledTimes(3);
expect(result?.attachments).toHaveLength(1);
} finally {
jest.useRealTimers();
}
});
it('keeps re-applying past unfinished partial rows until a finalized row is patched', async () => {
jest.useFakeTimers();
try {
processCodeOutput.mockResolvedValue({ file: { file_id: 'f1' } });
/* A disconnect mid-turn persists an unfinished partial row; the later
* finalize save overwrites it with the in-memory handle JSON, so a
* patch that settled on the partial row must not stop the loop. */
const updateToolCallResult = jest
.fn()
.mockResolvedValueOnce({ matched: true, unfinished: true })
.mockResolvedValue({ matched: true, unfinished: false });
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
const promise = handler(baseParams);
await jest.advanceTimersByTimeAsync(250);
const result = await promise;
expect(updateToolCallResult).toHaveBeenCalledTimes(2);
expect(result?.attachments).toHaveLength(1);
} finally {
jest.useRealTimers();
}
});
it('still patches output when a file download fails (files are best-effort)', async () => {
processCodeOutput.mockRejectedValue(new Error('download failed'));
const updateToolCallResult = jest.fn().mockResolvedValue({ matched: true, unfinished: false });
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
const result = await handler(baseParams);
expect(updateToolCallResult).toHaveBeenCalledWith(
expect.objectContaining({
output: 'stdout:\nhello',
attachments: [],
markBackgrounded: true,
}),
);
expect(result).toEqual({ attachments: [] });
});
it('reapply mode re-applies the row patch without reprocessing files', async () => {
const updateToolCallResult = jest.fn().mockResolvedValue({ matched: true, unfinished: false });
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
const result = await handler({
...baseParams,
artifact: undefined,
attachments: [{ file_id: 'f1' }],
reapply: true,
});
expect(processCodeOutput).not.toHaveBeenCalled();
expect(updateToolCallResult).toHaveBeenCalledTimes(1);
expect(updateToolCallResult).toHaveBeenCalledWith(
expect.objectContaining({
messageId: 'msg-dispatch',
toolCallId: 'call_code',
output: 'stdout:\nhello',
attachments: [{ file_id: 'f1' }],
/** The heal path must re-stamp the marker: the full-row save it
* repairs reverted the whole patched part, marker included. */
markBackgrounded: true,
}),
);
expect(result).toEqual({ attachments: [{ file_id: 'f1' }] });
});
it('returns null without identity to anchor to', async () => {
const updateToolCallResult = jest.fn();
const handler = createBackgroundCodeResultHandler({ req, updateToolCallResult });
expect(await handler({ ...baseParams, messageId: undefined })).toBeNull();
expect(updateToolCallResult).not.toHaveBeenCalled();
});
});