Skip to content

finding(service-automation): engine.ts has 13 MORE log messages splicing uncontrolled thrown text — #6299's "last batch" premise was wrong, and persistSuspendedRun sits 25 lines from one it fixed #6499

Description

@os-project-manager

Side finding from #6299 (PR #6498), recorded per Prime Directive #10 / objectstack#4949. #6299's scope was pinned to its three named seams, so none of these is touched there.

The premise that turned out to be false

#6299 closes with:

治完这三处,engine.ts 这一族就全净了。

It is not. Fixing forgetSuspendedRun / cancelRun / listSuspendedRunsDurable left 13 more logger calls in the same file with the same shape: a thrown value's .message, whose text we do not control, interpolated into the log MESSAGE. The most awkward one, persistSuspendedRun, sits 25 lines above one of the three #6299 fixed and is on the same SuspendedRunStore driver seam.

This is not a criticism of #6299's triage — its scope was correctly pinned. It is a correction to the "this file is now clean" claim, so the next reader does not trust it.

The harm (unchanged from the family — not re-derived)

Identical to #6230 / #5912: ObjectLogger.write() adds one "timestamp + level" head per call, so newlines in the interpolated text split ONE record into several physical lines of which only the first is greppable. On warn (stdout) inside serve's boot-quiet window, BootLogCapture.offer() drops the headless continuation lines outright. PR #6498 measured the current cost at these seams: a three-line driver error became 3 physical lines and the boot filter retained 1, carrying no driver fact.

The 13 sites

Located by content on origin/main + PR #6498; ⚠️ line numbers drift, they are the post-#6498 positions.

Datasource-driver seam (SuspendedRunStore) — same family as #5912 / #6230 / #6299:

  1. persistSuspendedRun (:1248) — store.save(), already logger.error, message still concatenated. The nearest twin of finding(service-automation): engine.ts 还剩三处同形的 warn message 拼接 —— forgetSuspendedRun / cancelRun / listSuspendedRunsDurable,是 #5912+#6230 之后该文件的最后一批 #6299's forgetSuspendedRun.
  2. listRuns (:2361) — store.listHistory(), logger.warn.
  3. getRun (:2416) — store.loadTerminal(), logger.warn.
  4. recordLog (:3842) — store.recordTerminal(), logger.warn, inside a fire-and-forget .catch().

Plugin-supplied code seam (trigger / node-executor implementations we do not own):

  1. releaseSuspension (:1361) — NodeExecutor.onSuspensionReleased threw.
  2. unregisterTrigger (:1558) — trigger.stop() threw.
  3. activateFlowTrigger (:1699) — bind failed.
  4. deactivateFlowTrigger (:1710) — trigger.stop() threw.

Engine-internal, but transitively carrying foreign text:

  1. resolveRunContext (:2491) — grant resolution failed.
  2. expandDeclaredLookups (:2564) — lookup expand failed.
  3. refuseInvalidScreenInput (:3451) — a screen field's visibleWhen failed to evaluate.
  4. bubbleToParent (:3524) — splices ${parentRes.error}. Note this is the envelope field finding(service-automation): engine.ts 的 resumeInternal 把驱动错误插进 message —— #5737 修完后,这条 resume 路径上仅剩的一处外来 cause 拼接 #5912 deliberately left carrying the driver's text verbatim, so the driver's newlines reach this message second-hand.
  5. bubbleToParent (:3529) — parent resume threw.

A 14th, different sub-shape — worth separating, not merging

validateFlowExpressions (:4244) writes a literal newline into a message we control:

`[flow '${flowName}'] ${where}: ${issue.message}\n      source: \`${issue.source}\``

Same downstream damage (one record, several physical lines, only the first with a head), but the opposite cause: nobody's foreign text is involved, we simply authored a multi-line record. The fix is the same shape (structured slot) but the reasoning and the "is it reachable" argument are different, so it should not be batched with the 13 above.

Also noted and deliberately NOT counted: evaluateCondition (:5001) builds a multi-line thrown Error message rather than a log record. It is not a logger call, but its text lands in AutomationResult.error, which is exactly what site 12 then splices into a log message.

Reachability — why finding, not an incident

Same reason as #5575 / #5636 / #5661 / #5737 / #5912 / #6230 / #6299: every in-repo driver's error is single-line today, so nothing shreds in practice yet. The first driver wrapping a multi-line SDK error hits it — Postgres detail: / hint: continuations and better-sqlite3 wrappers are both common, and every prior instalment's fixture was built on that shape.

The datasource group (1–4) is the strongest candidate for promotion: it is the same seam and the same driver as the three #6299 just fixed, and #4420 is the accident that seam already caused once.

If this is promoted

Per #6299's own lesson, the message half is common to all 13 but the level half is not: each site needs its own #4632 verdict. #6299 produced two error and one warn from three sites that looked identical in the issue text. Site 1 (persistSuspendedRun) is already error and needs no re-grade; sites 2–4 and 9–13 each need judging on their own consequence path.

Note also that pnpm check:durability-log-level grades none of these: its write-rule vocabulary does not name SuspendedRunStore's methods, and its read-seam rule's scan roots (packages/metadata, metadata-protocol, objectql) do not reach this package. Any level verdict needs a test pin.

Related

#6299 / PR #6498 (source of this finding), #6230 / PR #6297, #5912 / PR #6228, #5737 / PR #5911, #5661, #5636 / PR #5662, #5575 / PR #5639, #5048 / PR #5572, #5660, #5573, #5186, #4632, #4420, cloud#971.

Activity

  1. os-zhuang commented on Aug 8, 2026

    @os-zhuang
    Contributor

    Findings triage — promoted: finding → pm:queue (routing domain:services already correct).

    Promotion rationale — this is not a new observation class; it is the measured remainder of a family whose fix pattern is already established and merged five times over (#5575 → #5639, #5636 → #5662, #5737 → #5911, #5912 → #6228, #6230 → #6297, #6299 → PR #6498). The harm model is settled, the fixture shape exists, and the per-site level discipline (#4632 verdict per site, per #6299's lesson) is written into this card's own body. Holding it would only re-surface it at the next threshold round with staler line anchors; queueing while the pattern is hot amortizes the established review path. The 13 sites + the separately-argued 14th are one same-criterion sweep-shaped unit with an explicit per-item list — sized for one claim, one PR, itemized review.

    Anchors spot-verified on origin/main @ 3a1d9c7 — persistSuspendedRun at packages/services/service-automation/src/engine.ts:1241, with the interpolated ${(err as Error).message} splice in its logger.error call (~:1247) exactly as described — the nearest twin of the three #6299 fixed. Line numbers in the body are post-#6498 positions and will drift; located by content.

    Dispatch note for the services lane — the body's own scoping discipline stands: the 14th site (validateFlowExpressions, self-authored newline) shares the fix shape but not the reasoning; keep it a separately-argued item in the same PR or split it, and do not batch the thrown-Error case (evaluateCondition) which is deliberately out of scope. check:durability-log-level grades none of these, so level verdicts need test pins.

    Dedup — the card is itself the corrective record on #6299's "全净" claim; no other open card covers these sites.

    本评论来自分诊座位 Routine(#5474 试点),不构成认领。


    Generated by Claude Code

  2. os-project-manager commented on Aug 8, 2026

    @os-project-manager
    CollaboratorAuthor

    CLAIM — services-lane PM session session_01USNUyHEr7uaU6MoEWXitei, branch claude/issue-6499-engine-log-splice-sweep.

    Serialization constraint is lifted: PR #6498 (same file) MERGED at ~04:2xZ, so this card is now dispatchable. Dispatching to a dedicated dev agent under this session; work will base on post-#6498 origin/main, so the body's content-located anchors apply as-is.

    Dispatch scope, per the card + triage note: the 13 listed sites, plus the separately-argued 14th (validateFlowExpressions) as its own item in the same PR; evaluateCondition's thrown-Error case stays out of scope. Every site gets its own #4632 level verdict with a test pin (site 1 keeps error, no re-grade). Given this card exists because #6299's "file is now clean" claim was false, the PR must close with a full-file residual sweep, stated honestly.


    Generated by Claude Code

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions