diff --git a/.changeset/22073-boot-warning-one-line-per-class.md b/.changeset/22073-boot-warning-one-line-per-class.md new file mode 100644 index 0000000000..b45306b5d9 --- /dev/null +++ b/.changeset/22073-boot-warning-one-line-per-class.md @@ -0,0 +1,13 @@ +--- +"@objectstack/cli": patch +"@objectstack/plugin-auth": patch +--- + +The startup banner prints one line per warning class, each warning appears once, and a localhost boot no longer warns that OAuth is unencrypted. + +Clause-②: no + +- **One line per class.** Flows that declare a trigger but are not bound are grouped by trigger type and reason, with the flows listed: `⚠ 8 flows declare a 'schedule' trigger but are NOT bound — disabled by deployment policy — … (OS_AUTOMATION_SCHEDULED_WORK_ENABLED is unset or not truthy), so no time trigger arms …: flow_a, flow_b, …`. Before, the full reason (up to ~650 characters) printed once per flow. The banner now shows the reason's first sentence; `--log-level debug` still streams each flow's full reason. A real binding failure, or a missing trigger, keeps its own line, worded as before. +- **Printed once.** *Boot diagnostics* no longer repeats the automation plugin's per-flow `… is NOT bound` and shadowed-flow warnings, which the banner's `Flows:` list already shows. Its header counts them instead: `⚠ Boot diagnostics — 5 warnings logged during startup (8 more already listed above):`. Every other boot warning replays exactly as before. A boot that fails before the banner still replays all of them. +- **OAuth on loopback.** `OAuth is served UNENCRYPTED: …` is logged at `info` when the issuer's host is loopback (`localhost`, `*.localhost`, `127.0.0.0/8`, `::1`), so it is not shown at the default `warn` level. It stays `warn` on a private or link-local issuer. The sentence and the transport rule are unchanged. +- ⛔ Nothing you author changes. Which flows bind, the scheduled-work switch, the transport rule, the service-automation warning an embedded host reads, and every public key, export and parameter are unchanged. diff --git a/docs/qa/platform-checklist/areas/ai.json b/docs/qa/platform-checklist/areas/ai.json index 4e7e706845..89072f00a2 100644 --- a/docs/qa/platform-checklist/areas/ai.json +++ b/docs/qa/platform-checklist/areas/ai.json @@ -690,7 +690,7 @@ "title": "the MCP OAuth transport rule is judged on the DEPLOYMENT's own host: a private / link-local plain-HTTP deployment serves the OAuth track and logs the accepted-transport warning; a public plain-HTTP one is still refused, fail-closed, and logs its own public-plaintext warning", "since": "v17", "status": "active", - "revision": 2, + "revision": 3, "priority": "P1", "surface": "api", "fixtures": { @@ -714,7 +714,7 @@ "on boot (a), POST /api/v1/mcp with NO credentials; record the 401 and its WWW-Authenticate header, including whether a resource_metadata pointer is present", "if a second machine is available, drive a real MCP client from it against boot (a) over http:// and record whether the client completes the OAuth flow, refuses the scheme up front, or fails elsewhere — RECORD WHICH, because a client-side scheme refusal changes what this compatibility is worth", "boot (b) on a PUBLIC host spelling over plain http; capture the boot log and GET both protected-resource paths; record status and body — and record separately whether the public-plaintext warning `OAuth discovery is served over PUBLIC plain HTTP` appears and how many times", - "boot (c) on loopback; capture the boot log and the same two GETs", + "boot (c) on loopback with --log-level info (its accepted-transport line is logged at INFO there, so a default warn-level boot log does not carry it); capture the boot log and the same two GETs", "re-boot (a) with an https base URL (a self-signed terminator is enough — no client needs to trust it, only the deployment's own base URL has to be https); capture the boot log and record the ABSENCE of BOTH plain-HTTP warnings" ], "acceptance": [ @@ -731,9 +731,9 @@ "evidence": "the two 404s and the boot-log line" }, { - "clause": "eligibility decides WHICH plain-HTTP warning is emitted, never WHETHER one is: every plain-HTTP boot carries exactly one of the two, once, at mount. On a boot whose origin the transport rule ACCEPTS (a and c) it is the accepted-transport line `OAuth is served UNENCRYPTED`; on the PUBLIC plain-HTTP boot (b), whose OAuth track the same rule left dark, it is the distinct line `OAuth discovery is served over PUBLIC plain HTTP`, which states that the AS discovery surface is served over public plain HTTP, that the MCP OAuth track is disabled, and that TLS is the remedy. Neither line on the https re-boot. Each names the issuer URL. The ruled sentence 「OAuth 未加密:仅限可信内网」 is carried as the line's MEANING and lives verbatim in the code comment beside the call — ruling batch #210 item 5", + "clause": "eligibility decides WHICH plain-HTTP warning is emitted, never WHETHER one is: every plain-HTTP boot carries exactly one of the two, once, at mount. On a boot whose origin the transport rule ACCEPTS (a and c) it is the accepted-transport line `OAuth is served UNENCRYPTED` — logged at WARN on (a), and at INFO on loopback (c), where nothing crosses a network; on the PUBLIC plain-HTTP boot (b), whose OAuth track the same rule left dark, it is the distinct line `OAuth discovery is served over PUBLIC plain HTTP`, which states that the AS discovery surface is served over public plain HTTP, that the MCP OAuth track is disabled, and that TLS is the remedy. Neither line on the https re-boot. Each names the issuer URL. The ruled sentence 「OAuth 未加密:仅限可信内网」 is carried as the line's MEANING and lives verbatim in the code comment beside the call — ruling batch #210 item 5", "oracle": "log", - "verify": "grep the captured boot logs for the two ENGLISH anchors separately — `OAuth is served UNENCRYPTED`: exactly 1 on (a), exactly 1 on (c), 0 on (b), 0 on the https re-boot; `OAuth discovery is served over PUBLIC plain HTTP`: exactly 1 on (b), 0 on (a), 0 on (c), 0 on the https re-boot. Each matched line names the issuer, the origin followed by /api/v1/auth. ⛔ Grepping for 「OAuth 未加密:仅限可信内网」 now returns 0 on every boot: ruling batch #210 item 5 moved that sentence out of the emitted string into the code comment, so a run still greping it scores every boot as a miss", + "verify": "grep the captured boot logs for the two ENGLISH anchors separately — `OAuth is served UNENCRYPTED`: exactly 1 on (a), at WARN; exactly 1 on (c), at INFO, in its --log-level info boot log (0 in a default warn-level one); 0 on (b), 0 on the https re-boot; `OAuth discovery is served over PUBLIC plain HTTP`: exactly 1 on (b), 0 on (a), 0 on (c), 0 on the https re-boot. Each matched line names the issuer, the origin followed by /api/v1/auth. ⛔ Grepping for 「OAuth 未加密:仅限可信内网」 now returns 0 on every boot: ruling batch #210 item 5 moved that sentence out of the emitted string into the code comment, so a run still greping it scores every boot as a miss", "evidence": "the matching log lines with their counts, and the two empty results (the public boot and the https re-boot)" }, { @@ -783,6 +783,12 @@ "date": "2026-09-22", "change": "ruling batch #210 item 5 (B/B). D1: eligibility decides WHICH plain-HTTP warning is emitted, never WHETHER one is — boot (b) moves from asserting 0 warnings to asserting exactly 1 occurrence of a new, distinct public-plaintext line, because the .well-known discovery routes are mounted regardless of transport while the 'OAuth track is NOT live' line sits inside the MCP-surface condition, so a public plain-HTTP boot with that surface off used to emit nothing at all. D2: the emitted strings are English and the grep anchors move to them; the ruled Chinese sentence is carried as the line's meaning in the code comment beside the call. Steps, clauses and verifies moved together", "ref": "claude/issue-19571-plaintext-as-warning" + }, + { + "revision": 3, + "date": "2026-10-07", + "change": "the accepted-transport line `OAuth is served UNENCRYPTED` is logged at INFO when the issuer's host is loopback and stays WARN on a private or link-local one (triage ruling on #22073), so boot (c)'s line no longer shows at the default warn level. steps[5] boots (c) with --log-level info; acceptance[2]'s clause and verify name the level per boot. D1 is unchanged: the same sentence is still emitted on every accepted plain-HTTP boot", + "ref": "#22073" } ] } diff --git a/docs/qa/platform-checklist/areas/platform-core.json b/docs/qa/platform-checklist/areas/platform-core.json index 9913ecc61e..255a202b50 100644 --- a/docs/qa/platform-checklist/areas/platform-core.json +++ b/docs/qa/platform-checklist/areas/platform-core.json @@ -9,7 +9,7 @@ "title": "Showcase boots clean: health + ready 200, no degraded startup banners, console + app metadata served", "since": "v15", "status": "active", - "revision": 6, + "revision": 7, "priority": "P0", "surface": "mixed", "preconditions": [ @@ -40,7 +40,7 @@ { "clause": "the `Flows:` startup banner carries no ⚠ line of a MISAUTHORED class — a flow name claimed by several definitions, a flow targeting an unknown object, a trigger NOT bound for any reason other than deployment policy, or flows declared while the automation engine is not enabled — and no ERROR-level lines appear IN THE BOOT WINDOW — the window is part of the clause, because ordinary caller-error 4xx traffic also logs at ERROR", "oracle": "log", - "verify": "read each ⚠ line under the Flows banner and classify it. ⚠️ A stock boot DOES print ⚠ lines that are not misauthoring: each package-authored scheduled flow is listed as `⚠ flow '' declares a '' trigger but is NOT bound — disabled by deployment policy …`, because package-authored scheduled work is off by default (QA run #21056 counted two on stock showcase). That is the posture working, so a bare grep for '⚠' reads a clean boot as a FAIL (the four misauthored classes are the four ⚠ shapes printAutomationSummary in packages/cli/src/utils/format.ts prints). Then grep for ERROR lines, SCOPED to the boot window — from process start to the first 200 on /api/v1/health (the same instant clause 0 records as time-to-healthy). ⚠️ A caller-error REFUSAL logs at ERROR level with a full stack BEFORE answering 4xx — measured on 17.1.0 with a `$fn` filter probe answering 400 INVALID_FILTER (#10257). So an unscoped grep over a log that also carries the run's own probe traffic reports ERROR lines for requests the platform refused CORRECTLY, and a clean boot reads as a boot failure. Cut the log at the health-green line before grepping, or capture the boot log to its own file before issuing the first request; seed rejections still count as failures (see #3415 — SeedLoader rejections were silent)", + "verify": "read each ⚠ line under the Flows banner and classify it. ⚠️ A stock boot DOES print ⚠ lines that are not misauthoring: package-authored scheduled flows are listed on ONE line per trigger type and reason, `⚠ flow(s) declare a '' trigger but are NOT bound — disabled by deployment policy …: `, because package-authored scheduled work is off by default (QA run #21056 counted two such flows on stock showcase; since #22073 they share one line, and Boot diagnostics no longer repeats them). That is the posture working, so a bare grep for '⚠' reads a clean boot as a FAIL (the four misauthored classes are the four ⚠ shapes printAutomationSummary in packages/cli/src/utils/format.ts prints). Then grep for ERROR lines, SCOPED to the boot window — from process start to the first 200 on /api/v1/health (the same instant clause 0 records as time-to-healthy). ⚠️ A caller-error REFUSAL logs at ERROR level with a full stack BEFORE answering 4xx — measured on 17.1.0 with a `$fn` filter probe answering 400 INVALID_FILTER (#10257). So an unscoped grep over a log that also carries the run's own probe traffic reports ERROR lines for requests the platform refused CORRECTLY, and a clean boot reads as a boot failure. Cut the log at the health-green line before grepping, or capture the boot log to its own file before issuing the first request; seed rejections still count as failures (see #3415 — SeedLoader rejections were silent)", "evidence": "the grepped log excerpt" }, { @@ -90,6 +90,12 @@ "date": "2026-10-01", "change": "checklist-accuracy findings of QA run #21056. steps[3] asked for every SeedLoader line, but at the default warn level a healthy boot prints none: it now names the level-immune `Seeds:` banner row and the --log-level info line. acceptance[2]'s 'no ⚠' collided with the stock `NOT bound — disabled by deployment policy` lines for package-authored scheduled flows: the clause now names the misauthored classes it fails on", "ref": "#21060" + }, + { + "revision": 7, + "date": "2026-10-07", + "change": "acceptance[2].verify quoted the per-flow banner line `⚠ flow '' declares a '' trigger but is NOT bound — disabled by deployment policy …`. The banner now prints one line per (trigger type, reason) class with the flows listed, and Boot diagnostics no longer repeats the automation plugin's per-flow line, so the quoted shape moved with it. The clause is unchanged", + "ref": "#22073" } ] }, diff --git a/packages/cli/src/utils/format.boot-warning-classes.test.ts b/packages/cli/src/utils/format.boot-warning-classes.test.ts new file mode 100644 index 0000000000..d283c55842 --- /dev/null +++ b/packages/cli/src/utils/format.boot-warning-classes.test.ts @@ -0,0 +1,376 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { LiteKernel, type Plugin, type PluginContext } from '@objectstack/core'; +import { AutomationServicePlugin } from '@objectstack/service-automation'; +import { SCHEDULED_WORK_DISABLED_REASON, SCHEDULED_WORK_ENV } from '@objectstack/types'; +import { + printBootDiagnostics, + printServerReady, + type AutomationReadySummary, + type ServerReadyOptions, +} from './format.js'; +import { BootLogCapture } from './boot-log-capture.js'; +import { collectAutomationSummary } from '../commands/serve.js'; + +/** + * #22073 — one boot line per warning class, and each warning printed once. + * + * ## What the boot looked like + * + * Measured on hotcrm (17.7.0): an app with eight package-authored scheduled + * flows, on a deployment with scheduled work off (the default), printed the + * same ~600-character paragraph SIXTEEN times — once per flow in the banner's + * `Flows:` list, and once per flow again in *Boot diagnostics*, which replays + * `@objectstack/service-automation`'s own `kernel:bootstrapped` audit warning + * for the same flows. Sixteen of a 66-line boot, burying the five real + * warnings beside them. + * + * ## The pins (triage ruling on #22073) + * + * - an app with eight scheduled flows prints ONE schedule line; + * - no warning appears twice — banner list OR Boot diagnostics, not both; + * - (the loopback OAuth line is `@objectstack/plugin-auth`'s, pinned in + * its own `mcp-oauth-plaintext-notice.test.ts`). + * + * ## Why one leg boots the REAL producer + * + * The print-once rule works by the banner naming the logger records it + * restated, so it is only as good as its agreement with the wording + * `@objectstack/service-automation` actually emits. A formatter test fed + * hand-written records would stay green through a reworded producer while + * the boot doubled again. So the first describe block boots the real + * `AutomationServicePlugin` on a `LiteKernel`, captures its stdout through the + * same `BootLogCapture` `serve` uses, reads the summary through the same + * `collectAutomationSummary`, and holds both pins against ONE transcript. The + * formatter legs after it cover the shapes a real boot does not reach cheaply. + * + * ⚠️ The two `@objectstack/*` package imports resolve to their built `dist` + * (both are already in `KNOWN_UNALIASED_TEST_IMPORTS['@objectstack/cli']`; + * `turbo.json` builds dependencies before `@objectstack/cli#test`). + */ + +/** Eight names, none a substring of another, so a per-name line count is exact. */ +const SCHEDULED_FLOWS = [ + 'digest_daily', + 'reminder_weekly', + 'cleanup_nightly', + 'renewal_check', + 'sla_monitor', + 'invoice_sweep', + 'backup_ping', + 'quota_reset', +]; + +/** The deployment-policy reason's SECOND sentence — the long explanation. */ +const LONG_EXPLANATION = 'This is not a binding failure'; + +const BASE: ServerReadyOptions = { + externalBaseOrigin: 'http://localhost:3000', + isDev: true, + pluginCount: 3, +}; + +let transcript: string[]; +let errSpy: ReturnType; + +/** Strip SGR so assertions hold whether or not chalk colors this run. */ +const plain = (s: string) => s.replace(/\u001b\[[0-9;]*m/g, ''); + +const linesWith = (needle: string) => transcript.filter((line) => line.includes(needle)); + +beforeEach(() => { + transcript = []; + errSpy = vi.spyOn(console, 'error').mockImplementation((...args: unknown[]) => { + for (const line of plain(args.join(' ')).split('\n')) transcript.push(line); + }); +}); + +afterEach(() => { + errSpy.mockRestore(); +}); + +/** A package-authored `schedule` flow — the shape every hotcrm flow had. */ +const scheduleFlow = (name: string) => ({ + name, + label: name, + type: 'schedule', + runAs: 'system', + nodes: [ + { id: 'start', type: 'start', label: 'Start', config: { schedule: '0 8 * * *' } }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [{ id: 'e1', source: 'start', target: 'end' }], +}); + +/** + * The one `objectql` seam the automation plugin's boot pull reads — the same + * stand-in `@objectstack/service-automation`'s own plugin-path tests use, so + * the flows register on the real `start()` path. + */ +function fakeObjectqlPlugin(flows: unknown[]): Plugin { + return { + name: 'fake-objectql', + version: '1.0.0', + async init(ctx: PluginContext) { + (ctx as unknown as { registerService(n: string, s: unknown): void }).registerService('objectql', { + registry: { + listItems: (type: string) => (type === 'flow' ? flows : []), + getObject: () => undefined, + }, + }); + }, + }; +} + +describe('a real automation boot with eight scheduled flows and scheduled work off', () => { + let priorSwitch: string | undefined; + beforeEach(() => { + priorSwitch = process.env[SCHEDULED_WORK_ENV]; + delete process.env[SCHEDULED_WORK_ENV]; + }); + afterEach(() => { + if (priorSwitch === undefined) delete process.env[SCHEDULED_WORK_ENV]; + else process.env[SCHEDULED_WORK_ENV] = priorSwitch; + }); + + /** + * Boot under a capture of stdout exactly as `serve`'s boot-quiet window + * does, then print the real banner from the real engine. + */ + async function bootAndPrintBanner(): Promise<{ captured: string[] }> { + const capture = new BootLogCapture(); + const outSpy = vi.spyOn(process.stdout, 'write').mockImplementation(((chunk: unknown, encoding?: unknown) => { + capture.write(chunk as string | Uint8Array, typeof encoding === 'string' ? encoding : undefined); + return true; + }) as never); + const kernel = new LiteKernel(); + kernel.use(fakeObjectqlPlugin(SCHEDULED_FLOWS.map(scheduleFlow))); + kernel.use(new AutomationServicePlugin()); + try { + await kernel.bootstrap(); + } finally { + outSpy.mockRestore(); + } + try { + const captured = capture.diagnostics(); + printServerReady({ + ...BASE, + automation: collectAutomationSummary(kernel, SCHEDULED_FLOWS.length), + bootDiagnostics: { lines: captured, dropped: capture.droppedCount }, + }); + return { captured }; + } finally { + await kernel.shutdown(); + } + } + + it('prints ONE schedule line, naming all eight flows', async () => { + const { captured } = await bootAndPrintBanner(); + + // The premise, asserted first: the producer really warned once per flow + // into the capture — without it the print-once assertion below is vacuous. + for (const name of SCHEDULED_FLOWS) { + expect( + captured.filter((record) => record.includes(`'${name}'`) && record.includes('NOT bound')), + `the automation plugin emitted no bootstrap warning for '${name}'`, + ).toHaveLength(1); + } + + const scheduleLines = linesWith("a 'schedule' trigger"); + expect(scheduleLines, transcript.join('\n')).toHaveLength(1); + expect(scheduleLines[0]).toContain('8 flows declare'); + expect(scheduleLines[0]).toContain('NOT bound'); + for (const name of SCHEDULED_FLOWS) expect(scheduleLines[0]).toContain(name); + // The class's short text is the reason's first sentence — cause and switch. + expect(scheduleLines[0]).toContain('disabled by deployment policy'); + expect(scheduleLines[0]).toContain(SCHEDULED_WORK_ENV); + }); + + it('prints no warning twice — every flow named on exactly one line', async () => { + await bootAndPrintBanner(); + + for (const name of SCHEDULED_FLOWS) { + expect(linesWith(name), `'${name}' is named on more than one line:\n${transcript.join('\n')}`).toHaveLength(1); + } + // The long explanation is not on the default-level screen at all; it is + // what `--log-level debug` streams (the producer's own per-flow line). + expect(linesWith(LONG_EXPLANATION)).toEqual([]); + }); +}); + +/** The audit entries the engine reports for flows refused by deployment policy. */ +const policyRefused = (names: string[], triggerType = 'schedule'): AutomationReadySummary['unbound'] => + names.map((flowName) => ({ flowName, triggerType, reason: SCHEDULED_WORK_DISABLED_REASON })); + +const summary = (over: Partial): AutomationReadySummary => ({ + enabled: true, + declaredFlowCount: 0, + flowCount: 10, + boundCount: 0, + triggerTypes: ['schedule', 'record_change'], + unbound: [], + unknownObject: [], + shadowed: [], + draftCount: 0, + ...over, +}); + +/** + * One captured record as `ObjectLogger`'s pretty format renders it — the shape + * `BootLogCapture` retains (the real-boot block above reads the real one). + */ +const record = (message: string) => `2026-10-07T13:47:40.255Z WARN ${message}`; + +/** `@objectstack/service-automation`'s bootstrap audit line for one flow. */ +const auditRecord = (name: string, triggerType = 'schedule', reason = SCHEDULED_WORK_DISABLED_REASON) => + record(`[Automation] flow '${name}' declares a '${triggerType}' trigger but is NOT bound — it will never auto-launch. ${reason}`); + +describe('one line per warning class (formatter)', () => { + it('keeps distinct (trigger type, reason) classes on distinct lines, in first-seen order', () => { + const missingTrigger = + "no 'schedule' trigger is registered — add requires: ['triggers'] (record_change/schedule/time_relative/api ship in @objectstack/trigger-*)"; + const bindingFailed = "trigger 'record_change' is registered but binding failed — see earlier warnings"; + printServerReady({ + ...BASE, + automation: summary({ + unbound: [ + ...policyRefused(['a_flow', 'b_flow']), + { flowName: 'c_flow', triggerType: 'schedule', reason: missingTrigger }, + { flowName: 'd_flow', triggerType: 'record_change', reason: bindingFailed }, + ...policyRefused(['e_flow'], 'time_relative'), + ], + }), + }); + + const classLines = linesWith('NOT bound'); + expect(classLines).toHaveLength(4); + expect(classLines[0]).toContain("2 flows declare a 'schedule' trigger but are NOT bound — disabled by deployment policy"); + expect(classLines[0]).toMatch(/: a_flow, b_flow$/); + // A one-sentence reason comes back whole — its remedy included. + expect(classLines[1]).toBe(` ⚠ 1 flow declares a 'schedule' trigger but is NOT bound — ${missingTrigger}: c_flow`); + expect(classLines[2]).toBe(` ⚠ 1 flow declares a 'record_change' trigger but is NOT bound — ${bindingFailed}: d_flow`); + // Same reason, different trigger type ⇒ its own class. + expect(classLines[3]).toContain("1 flow declares a 'time_relative' trigger but is NOT bound — disabled by deployment policy"); + }); + + it('cuts a long reason to its first sentence, and says where the rest prints', () => { + printServerReady({ ...BASE, automation: summary({ unbound: policyRefused(['a_flow']) }) }); + + const firstSentence = SCHEDULED_WORK_DISABLED_REASON.slice(0, SCHEDULED_WORK_DISABLED_REASON.indexOf('. This')); + expect(linesWith('NOT bound')).toEqual([ + ` ⚠ 1 flow declares a 'schedule' trigger but is NOT bound — ${firstSentence}: a_flow`, + ]); + expect(linesWith(LONG_EXPLANATION)).toEqual([]); + expect(linesWith('--log-level debug')).toHaveLength(1); + }); + + it('prints no shortening hint when every reason is already one sentence', () => { + printServerReady({ + ...BASE, + automation: summary({ + unbound: [{ flowName: 'a_flow', triggerType: 'api', reason: "no 'api' trigger is registered — add requires: ['triggers']" }], + }), + }); + expect(linesWith('NOT bound')).toHaveLength(1); + expect(linesWith('--log-level debug')).toEqual([]); + }); +}); + +describe('print-once: Boot diagnostics withholds what the banner restated (formatter)', () => { + // A boot warning no banner section restates. Shaped as the runtime-assets + // plugin's branding warning (`describeUnservedBrandingAssets` in + // `console.ts`, #22071) renders it — the first new boot warning to land + // beside this rule, which must keep it single. + const unrelated = record( + "Branding asset not served: app 'crm' (branding.logo, branding.favicon) → /runtime/assets/icon.svg, but " + + 'the directory searched, /srv/app/assets (the cwd/assets default, since OS_RUNTIME_ASSETS_DIR is unset), ' + + 'does not exist, so /runtime/assets/ is not mounted this run; the console will draw a broken image. To fix, ' + + 'put icon.svg in that directory and restart, or set OS_RUNTIME_ASSETS_DIR to the directory that holds it.', + ); + + it('replays every other record exactly once, and counts the withheld ones', () => { + const names = ['a_flow', 'b_flow', 'c_flow']; + printServerReady({ + ...BASE, + automation: summary({ unbound: policyRefused(names) }), + bootDiagnostics: { lines: [...names.map((n) => auditRecord(n)), unrelated] }, + }); + + for (const name of names) expect(linesWith(name), transcript.join('\n')).toHaveLength(1); + // A boot warning no banner section restates — the branding warning #22071 + // added included — prints once, in Boot diagnostics: neither doubled nor + // dropped. + expect(linesWith('Branding asset not served')).toHaveLength(1); + expect(linesWith('/runtime/assets/icon.svg')).toHaveLength(1); + expect(linesWith('Boot diagnostics')).toEqual([ + ' ⚠ Boot diagnostics — 1 warning logged during startup (3 more already listed above):', + ]); + }); + + it('prints no Boot diagnostics block when the banner restated every record', () => { + printServerReady({ + ...BASE, + automation: summary({ unbound: policyRefused(['a_flow']) }), + bootDiagnostics: { lines: [auditRecord('a_flow')] }, + }); + expect(linesWith('Boot diagnostics')).toEqual([]); + expect(linesWith('a_flow')).toHaveLength(1); + }); + + it('withholds a JSON-format record too', () => { + const json = JSON.stringify({ + time: '2026-10-07T13:47:40.255Z', + level: 'warn', + msg: `[Automation] flow 'a_flow' declares a 'schedule' trigger but is NOT bound — it will never auto-launch. ${SCHEDULED_WORK_DISABLED_REASON}`, + }); + printServerReady({ + ...BASE, + automation: summary({ unbound: policyRefused(['a_flow']) }), + bootDiagnostics: { lines: [json, unrelated] }, + }); + expect(linesWith('a_flow')).toHaveLength(1); + }); + + it('⛔ never withholds a record the banner did NOT restate — a flow it does not list stays', () => { + printServerReady({ + ...BASE, + automation: summary({ unbound: policyRefused(['a_flow']) }), + // b_flow's record without a banner line naming it: printed, not dropped. + bootDiagnostics: { lines: [auditRecord('a_flow'), auditRecord('b_flow')] }, + }); + expect(linesWith('b_flow')).toHaveLength(1); + expect(linesWith('b_flow')[0]).toContain("[Automation] flow 'b_flow'"); + }); + + it('withholds the shadowed-flow restatement, and keeps the pull-time collision record that explains it', () => { + const restatement = record( + "[Automation] flow 'dup_flow' is claimed by 2 definitions — package 'crm' is ARMED and a runtime-authored " + + 'row (sys_metadata) is shadowed (see the flow name collision warning for the rule that armed it). ' + + 'Only the armed definition dispatches.', + ); + const collision = record( + "[Automation] Flow name collision: 'dup_flow' is claimed by 2 definitions (package 'crm', a runtime-authored " + + "row (sys_metadata)); arming package 'crm' by package id, and shadowing 1 other definition(s). " + + 'Only the armed definition dispatches. Rename one of them.', + ); + printServerReady({ + ...BASE, + automation: summary({ + shadowed: [{ flowName: 'dup_flow', armed: { source: 'package', packageId: 'crm' }, shadowedCount: 1 }], + }), + bootDiagnostics: { lines: [collision, restatement] }, + }); + expect(linesWith('is ARMED')).toHaveLength(1); // the banner's line + expect(linesWith('Flow name collision')).toHaveLength(1); + expect(linesWith('Boot diagnostics')).toEqual([ + ' ⚠ Boot diagnostics — 1 warning logged during startup (1 more already listed above):', + ]); + }); + + it('with no banner (the failed-boot path) replays every record', () => { + printBootDiagnostics({ lines: [auditRecord('a_flow'), unrelated] }); + expect(linesWith('a_flow')).toHaveLength(1); + expect(linesWith('Boot diagnostics')).toEqual([' ⚠ Boot diagnostics — 2 warnings logged during startup:']); + }); +}); diff --git a/packages/cli/src/utils/format.ts b/packages/cli/src/utils/format.ts index ef41fa38e0..d47b791348 100644 --- a/packages/cli/src/utils/format.ts +++ b/packages/cli/src/utils/format.ts @@ -12,6 +12,7 @@ import type { SeedSettlementSnapshot } from '@objectstack/spec/contracts'; import type { DevLogin } from '@objectstack/spec/system'; import { writeStdoutDirect } from './json-stdout.js'; import { authoringRuleUnionStack } from './stack-collections.js'; +import { stripAnsi } from './boot-log-capture.js'; // ─── Constants ────────────────────────────────────────────────────── export const CLI_NAME = 'objectstack'; @@ -1218,13 +1219,18 @@ export function printServerReady(opts: ServerReadyOptions) { if (opts.pluginNames && opts.pluginNames.length > 0) { console.error(chalk.dim(` ${opts.pluginNames.join(', ')}`)); } - if (opts.automation) printAutomationSummary(opts.automation); + // [#22073] Print-once: every banner section that RESTATES a boot-phase logger + // record hands back the record it restated, at the moment it prints its own + // line, and `printBootDiagnostics` withholds exactly those. See + // {@link BootDiagnosticsReplayOptions.restatedAbove} for the rule. + const restatedAbove: string[] = []; + if (opts.automation) restatedAbove.push(...printAutomationSummary(opts.automation)); if (opts.seeds) printSeedSummary(opts.seeds); // #17329 — AFTER the settled summary, never instead of it: a bundle with two // config apps can have one finished (a real `Seeds:` row) and one still // writing, and reporting only the first is the omission this closes. if (opts.seedSettlement) printSeedsStillWriting(opts.seedSettlement); - if (opts.bootDiagnostics) printBootDiagnostics(opts.bootDiagnostics); + if (opts.bootDiagnostics) printBootDiagnostics(opts.bootDiagnostics, { restatedAbove }); console.error(''); console.error(chalk.dim(' Press Ctrl+C to stop')); console.error(''); @@ -1238,6 +1244,39 @@ export interface BootDiagnostics { dropped?: number; } +/** + * How {@link printBootDiagnostics} replays when the banner has already spoken + * (#22073). + */ +export interface BootDiagnosticsReplayOptions { + /** + * The print-once rule: a boot warning prints in the banner list OR in *Boot + * diagnostics*, never both. + * + * Each entry is the identifying text of ONE logger record a banner section + * restated — handed back by that section at the moment it printed its own + * line (today only `printAutomationSummary`, for the + * `@objectstack/service-automation` bootstrap audit it summarises). A + * replayed record containing one is withheld here; every other record + * prints, exactly once, as before. + * + * So a NEW boot warning stays single without anyone touching this code: a + * `logger.warn` that no banner section restates is never matched and replays + * once, and a banner line that is not also a logger record has nothing to + * withhold. A banner section that starts restating a logger record must hand + * that record back here — otherwise it prints twice, which is exactly what + * this field ends. + * + * The match fails in ONE direction only: a record the claim does not + * recognise (a reworded producer, an escaped character in a JSON-format + * record) is printed, never dropped. A doubled line is noise; a dropped one + * would be a silent diagnostic. Empty or absent ⇒ every line replays — the + * failed-boot and migrate-and-exit paths in `serve`, which print no banner, + * pass nothing. + */ + restatedAbove?: readonly string[]; +} + /** * Replay what the boot-quiet stdout window held back (#4012). * @@ -1251,20 +1290,33 @@ export interface BootDiagnostics { * boot and directly from serve's error path on a failed one — a boot that dies * is exactly when its warnings matter most. * + * [#22073] Print-once: from the banner it withholds the records a banner + * section already restated (`options.restatedAbove`), and its header counts + * them separately, so no warning appears in both places. + * * Replayed to **stderr** (#7915) — these are the kernel's own diagnostics, held * back and re-emitted, so they land where every other `serve` diagnostic does. */ -export function printBootDiagnostics(diagnostics: BootDiagnostics) { +export function printBootDiagnostics(diagnostics: BootDiagnostics, options: BootDiagnosticsReplayOptions = {}) { const { lines, dropped = 0 } = diagnostics; - if (lines.length === 0) return; + const restated = options.restatedAbove ?? []; + const isRestated = (line: string): boolean => { + if (restated.length === 0) return false; + const text = stripAnsi(line); + return restated.some((record) => text.includes(record)); + }; + const shown = lines.filter((line) => !isRestated(line)); + const listedAbove = lines.length - shown.length; + if (shown.length === 0 && dropped === 0) return; console.error(''); console.error( chalk.yellow( - ` ⚠ Boot diagnostics — ${lines.length} warning${lines.length === 1 ? '' : 's'} logged during startup:`, + ` ⚠ Boot diagnostics — ${shown.length} warning${shown.length === 1 ? '' : 's'} logged during startup` + + `${listedAbove > 0 ? ` (${listedAbove} more already listed above)` : ''}:`, ), ); - for (const line of lines) console.error(chalk.dim(` ${line}`)); + for (const line of shown) console.error(chalk.dim(` ${line}`)); if (dropped > 0) { console.error(chalk.dim(` …and ${dropped} more (capture buffer full)`)); } @@ -1285,12 +1337,70 @@ function describeFlowBody(c: { source: 'package' | 'runtime'; packageId?: string return c.packageId ? `package '${c.packageId}'` : 'a code-shipped package (id unknown)'; } +/** + * The banner's short form of one unbound-flow reason (#22073): its FIRST + * SENTENCE, trailing period dropped. + * + * Derived, never hand-copied: the engine owns every reason sentence + * (`describeUnboundReason` in `@objectstack/service-automation`, and for the + * deployment policy `scheduledWorkDisabledReason` in `@objectstack/types`), and + * a second, banner-side wording of any of them would be free to drift from it. + * The reasons are written cause-first, so the first sentence carries the cause + * and the switch it names — for the deployment policy, `disabled by deployment + * policy — … (OS_AUTOMATION_SCHEDULED_WORK_ENABLED is unset or not truthy), so + * no time trigger arms …`. What follows it (that this is not a binding failure, + * the default in every posture) is the long explanation, and it prints at + * `--log-level debug`: the boot stream is live there, and it carries + * `@objectstack/service-automation`'s per-flow bootstrap warning, which keeps + * the whole reason. A reason that is one sentence already (a missing trigger, + * a binding failure, a declined subflow) comes back whole. + * + * A sentence ends at a period followed by whitespace and a capital — so + * `e.g. foo`, `@objectstack/trigger-*` and `17.7.0` do not cut one short. + */ +function leadSentence(reason: string): string { + const text = reason.trim(); + const end = /\.\s+(?=[A-Z])/.exec(text); + return (end ? text.slice(0, end.index) : text).replace(/\.$/, ''); +} + +/** + * Group the binding audit into one warning class per (trigger type, reason) + * (#22073), each with its flows in audit order, classes in first-seen order. + * + * Keyed on the WHOLE reason, not its short form: two reasons that share a + * first sentence are still two facts, and a real binding failure keeps its own + * line beside the deployment-policy one. + */ +function unboundFlowClasses( + unbound: AutomationReadySummary['unbound'], +): Array<{ triggerType: string; reason: string; flowNames: string[] }> { + const classes = new Map(); + for (const u of unbound) { + const key = JSON.stringify([u.triggerType, u.reason]); + let entry = classes.get(key); + if (!entry) { + entry = { triggerType: u.triggerType, reason: u.reason, flowNames: [] }; + classes.set(key, entry); + } + entry.flowNames.push(u.flowName); + } + return [...classes.values()]; +} + /** * One-glance answer to "did my flows actually arm?" — the question the * boot-quiet stdout window otherwise makes unanswerable (the engine's own * bind/registration logs are swallowed during startup). + * + * Returns the boot-phase logger records it RESTATED (#22073), for + * {@link BootDiagnosticsReplayOptions.restatedAbove}: the identifying text of + * `@objectstack/service-automation`'s `kernel:bootstrapped` audit warning for + * each flow this banner names as NOT bound or as shadowed. Each is handed back + * where its banner line prints, so a line that does not print claims nothing. */ -function printAutomationSummary(a: AutomationReadySummary) { +function printAutomationSummary(a: AutomationReadySummary): string[] { + const restated: string[] = []; if (!a.enabled) { if (a.declaredFlowCount > 0) { console.error( @@ -1300,9 +1410,9 @@ function printAutomationSummary(a: AutomationReadySummary) { ), ); } - return; + return restated; } - if (a.flowCount === 0) return; + if (a.flowCount === 0) return restated; const parts = [`${a.flowCount} flow(s)`, `${a.boundCount} bound to triggers`]; if (a.triggerTypes.length > 0) parts.push(`(${a.triggerTypes.join(', ')})`); @@ -1321,11 +1431,33 @@ function printAutomationSummary(a: AutomationReadySummary) { `(ADR-0005 overlay precedence; only the armed definition dispatches)`, ), ); + // The engine's bootstrap restatement of the same receipt. Its pull-time + // `Flow name collision: …` warning is a different record — it says WHICH + // rule armed the body — and keeps its place in Boot diagnostics. + restated.push(`[Automation] flow '${s.flowName}' is claimed by ${s.shadowedCount + 1} definitions`); } - for (const u of a.unbound) { + // [#22073] One line per warning class — (trigger type, reason) — with its + // flows listed, instead of one ~600-character line per flow. An app with + // eight package-authored scheduled flows on a deployment with scheduled work + // off used to print the same paragraph eight times here and eight more in + // Boot diagnostics; it now prints one line. + let shortened = false; + for (const c of unboundFlowClasses(a.unbound)) { + const n = c.flowNames.length; + const short = leadSentence(c.reason); + if (short !== c.reason.trim().replace(/\.$/, '')) shortened = true; console.error( - chalk.yellow(` ⚠ flow '${u.flowName}' declares a '${u.triggerType}' trigger but is NOT bound — ${u.reason}`), + chalk.yellow( + ` ⚠ ${n} flow${n === 1 ? ' declares' : 's declare'} a '${c.triggerType}' trigger but ` + + `${n === 1 ? 'is' : 'are'} NOT bound — ${short}: ${c.flowNames.join(', ')}`, + ), ); + for (const flowName of c.flowNames) { + restated.push(`[Automation] flow '${flowName}' declares a '${c.triggerType}' trigger but is NOT bound`); + } + } + if (shortened) { + console.error(chalk.dim(" reasons cut to their first sentence — --log-level debug prints each flow's full reason")); } for (const u of a.unknownObject) { console.error( @@ -1335,6 +1467,7 @@ function printAutomationSummary(a: AutomationReadySummary) { ), ); } + return restated; } /** diff --git a/packages/plugins/plugin-auth/src/auth-plugin.ts b/packages/plugins/plugin-auth/src/auth-plugin.ts index 93a3bc6eff..14ed794d45 100644 --- a/packages/plugins/plugin-auth/src/auth-plugin.ts +++ b/packages/plugins/plugin-auth/src/auth-plugin.ts @@ -36,6 +36,7 @@ import { resolveOidcProviderEnabled, readMcpServerEnabledEnv, isOAuthEligibleBaseUrl, + ipMatchesRange, // [#16384] The one place `'/api/v1/auth'` is written — see its docblock in // auth-manager.ts. This file no longer carries an independent copy. DEFAULT_AUTH_BASE_PATH, @@ -251,9 +252,35 @@ export interface AuthPluginOptions extends Partial { hostSignInHandoff?: boolean; } +/** + * Is this plain-HTTP issuer on a LOOPBACK host (#22073)? Asked only of an issuer + * the transport rule has already accepted (`isOAuthEligibleBaseUrl`), to pick + * the plain-HTTP notice's level: loopback ⇒ `info`, private / link-local ⇒ + * `warn`. + * + * The loopback half of that rule's own allow-list, in its own terms: the + * `localhost` / `*.localhost` names it accepts, its `127.0.0.0/8` block judged + * by the same ADR-0069 D5 matcher (`ipMatchesRange`), and `::1`. The hostname + * is WHATWG-canonical, as the rule reads it — `127.1`, `0x7f.1` and + * `[0:0:0:0:0:0:0:1]` arrive here as `127.0.0.1` and `[::1]`. Every other + * accepted host — RFC 1918, link-local, unique-local — is not loopback and + * keeps the warning. `mcp-oauth-plaintext-notice.test.ts` pins both sides. + */ +function isLoopbackIssuer(issuer: string): boolean { + let host: string; + try { + host = new URL(issuer).hostname.toLowerCase(); + } catch { + return false; + } + if (host === 'localhost' || host.endsWith('.localhost')) return true; + if (host === '[::1]') return true; + return ipMatchesRange(host, '127.0.0.0/8'); +} + /** * Authentication Plugin - * + * * Provides authentication and identity services for ObjectStack applications. * * **Dual-Mode Operation:** @@ -3386,14 +3413,24 @@ export class AuthPlugin implements Plugin { const authIssuer = manager.getAuthIssuer(); const servedOverPlainHttp = /^http:\/\//i.test(authIssuer); if (servedOverPlainHttp && isOAuthEligibleBaseUrl(authIssuer)) { - ctx.logger.warn( + // [#22073] The LEVEL follows the host; the sentence does not. On a + // loopback issuer — every `os dev` / `os start` on localhost — nothing + // crosses a network at all, so the line is `info`: the same sentence, + // still emitted on every accepted plain-HTTP boot (D1 above holds), and + // no longer a warning about the expected local state on every boot. A + // private or link-local issuer is reachable from its network and keeps + // `warn`. Every OAuth origin this deployment publishes derives from the + // one canonical origin the issuer carries, so the issuer's host is the + // whole question. + const notice = 'OAuth is served UNENCRYPTED: this deployment publishes its ' + - `authorization server over plain HTTP (${authIssuer}), so authorization codes, access tokens ` + - 'and bearer headers cross the network in the clear and anything that can observe it can ' + - 'replay them. The transport rule accepts this origin only because the host is loopback or a ' + - 'private / link-local address; put TLS in front of any deployment reachable from a public ' + - 'network, where the same origin is refused outright.', - ); + `authorization server over plain HTTP (${authIssuer}), so authorization codes, access tokens ` + + 'and bearer headers cross the network in the clear and anything that can observe it can ' + + 'replay them. The transport rule accepts this origin only because the host is loopback or a ' + + 'private / link-local address; put TLS in front of any deployment reachable from a public ' + + 'network, where the same origin is refused outright.'; + if (isLoopbackIssuer(authIssuer)) ctx.logger.info(notice); + else ctx.logger.warn(notice); } else if (servedOverPlainHttp) { ctx.logger.warn( 'OAuth discovery is served over PUBLIC plain HTTP: this deployment publishes its ' + diff --git a/packages/plugins/plugin-auth/src/mcp-oauth-plaintext-notice.test.ts b/packages/plugins/plugin-auth/src/mcp-oauth-plaintext-notice.test.ts index 84710a9cc0..0725a05e3b 100644 --- a/packages/plugins/plugin-auth/src/mcp-oauth-plaintext-notice.test.ts +++ b/packages/plugins/plugin-auth/src/mcp-oauth-plaintext-notice.test.ts @@ -24,6 +24,12 @@ * here, and the two sentences are held distinct so a log grep can tell them * apart by count alone. * + * [#22073] The accepted line's LEVEL follows the host: `info` when the issuer + * is loopback (nothing crosses a network — it fired as a `warn` on every + * localhost boot), `warn` for a private or link-local issuer, which is the + * control. The sentence itself is unchanged and still emitted on every + * accepted plain-HTTP boot, so D1 holds across both levels. + * * ⚠️ The subject is `registerOidcDiscoveryRoutes` driven against a STUB * manager and a stub Hono app — it can answer "does the mount emit this * line", never "does the authorization server behave". Anything whose truth @@ -154,9 +160,40 @@ describe('plain-HTTP OAuth startup notice', () => { expect(notices[0]).not.toMatch(CJK_RANGE); }); - it('fires on a loopback deployment too — plain HTTP is plain HTTP', async () => { - const { warns } = await mountDiscoveryFor('http://localhost:3000'); + // [#22073] Flipped from `warn` on purpose (triage ruling on #22073: the line + // is `info` when every published origin is loopback). Every loopback + // spelling the transport rule accepts — the names, the whole 127.0.0.0/8 + // block, ::1, and WHATWG-canonicalised forms of them — gets the SAME + // sentence at `info`, and no warning. + it.each([ + 'http://localhost:3000', + 'http://app.localhost:3000', + 'http://127.0.0.1:3000', + 'http://127.0.0.2:3000', + 'http://127.1:3000', + 'http://[::1]:3000', + ])('logs the sentence at info, never warn, on a LOOPBACK deployment: %s', async (baseUrl) => { + const { warns, infos } = await mountDiscoveryFor(baseUrl); + expect(noticesIn(warns)).toHaveLength(0); + const notices = noticesIn(infos); + expect(notices).toHaveLength(1); + expect(notices[0]).toContain(`${new URL(baseUrl).origin}/api/v1/auth`); + }); + + // The control for the leg above: every NON-loopback host the rule accepts + // is reachable from its network and keeps the warning — RFC 1918, + // link-local in both families, and IPv6 unique-local. + it.each([ + 'http://10.0.0.5:3000', + 'http://172.16.0.1:3000', + 'http://192.168.1.10:3000', + 'http://169.254.10.20:3000', + 'http://[fd00::1]:3000', + 'http://[fe80::1]:3000', + ])('keeps the warning on a PRIVATE or LINK-LOCAL deployment: %s', async (baseUrl) => { + const { warns, infos } = await mountDiscoveryFor(baseUrl); expect(noticesIn(warns)).toHaveLength(1); + expect(noticesIn(infos)).toHaveLength(0); }); it('⛔ does NOT fire under TLS — neither sentence does', async () => { @@ -228,6 +265,8 @@ describe('plain-HTTP OAuth startup notice', () => { }); it('every plain-HTTP boot gets exactly one of the two sentences', async () => { + // [#22073] Counted across BOTH levels: the loopback line moved to `info`, + // and D1 is about whether a sentence is emitted, not at which level. const cases: Array<[string, number, number]> = [ ['http://localhost:3000', 1, 0], ['http://192.168.1.10:3000', 1, 0], @@ -235,8 +274,9 @@ describe('plain-HTTP OAuth startup notice', () => { ['http://203.0.113.5', 0, 1], ]; for (const [baseUrl, accepted, refused] of cases) { - const { warns } = await mountDiscoveryFor(baseUrl, { mcpServerEnabled: false }); - expect([baseUrl, noticesIn(warns).length, publicNoticesIn(warns).length]).toEqual([ + const { warns, infos } = await mountDiscoveryFor(baseUrl, { mcpServerEnabled: false }); + const emitted = [...warns, ...infos]; + expect([baseUrl, noticesIn(emitted).length, publicNoticesIn(emitted).length]).toEqual([ baseUrl, accepted, refused, @@ -260,7 +300,7 @@ describe('plain-HTTP OAuth startup notice', () => { expect(publicNoticesIn(warns)).toHaveLength(1); }); - it('is emitted at warn — a visibly smaller security posture, not a durability loss', async () => { + it('is emitted at warn on a private address — a visibly smaller security posture, not a durability loss', async () => { const { warns, infos } = await mountDiscoveryFor('http://172.16.0.1:3000'); expect(noticesIn(warns)).toHaveLength(1); expect(infos.filter((i) => i.includes(NOTICE_MARKER))).toHaveLength(0);