Skip to content

Fix: flush the CLI start-up diagnostic to stderr before exiting - #591

Open
AmaadMartin wants to merge 3 commits into
mainfrom
fix/integration-harness-port-allocation-and-diagnostics
Open

Fix: flush the CLI start-up diagnostic to stderr before exiting#591
AmaadMartin wants to merge 3 commits into
mainfrom
fix/integration-harness-port-allocation-and-diagnostics

Conversation

@AmaadMartin

@AmaadMartin AmaadMartin commented Aug 3, 2026

Copy link
Copy Markdown
Owner

Please ensure you have read the contribution guide before creating a pull request.

Link to Issue or Description of Change

  1. Link to an existing issue (if applicable):
    No existing issue. This targets the intermittently red windows-latest leg of the run-tests matrix in .github/workflows/validation.yaml.
  2. Or, if no issue exists, describe the change:

Problem: when adk web or adk api_server fails to start, the reason is routinely lost — and on Windows it is lost silently, which is what makes a flaky CI leg undebuggable.

Both commands did the same thing (dev/src/cli/cli.ts:253-256 and :298-301 on main):

} catch (error) {
  logger.error('Error starting API server:', (error as Error).message);
  process.exit(1);
}

Three defects in three lines:

  1. process.exit() outruns the write. Node documents that process.exit() terminates "even if there are still asynchronous operations pending … including I/O operations to process.stdout and process.stderr", and that writes to pipes are asynchronous on Windows (synchronous on POSIX). The log call and the exit are in the same synchronous block, so on Windows the diagnostic is very likely dropped. Winston adds at least a tick on top of that, because the record goes through a stream pipeline before it reaches the fd. On a POSIX dev machine the message lands; on a Windows runner writing to a captured pipe it does not — which is exactly the shape of "fails only on Windows, and says nothing when it does".
  2. It went to stdout, not stderr. AdkLogger's Console transport (dev/src/utils/logger.ts:72) is constructed without stderrLevels, so winston routes error-level records to stdout. A parent process listening on stderr for a failure reason hears nothing. (Fixing AdkLogger in general is out of scope here and is queued separately; this change stops the two fatal start-up paths depending on it.)
  3. Only .message survived. AdkApiServer.start() rejects for two very different reasons — the listen failed (EADDRINUSE/EACCES), or initA2A() threw while esbuild-bundling the agent fixtures. (error as Error).message throws away the stack, so the second case loses its location entirely.

This is the child-process half of the CLI exited prematurely with code 1 failure: exit code 1 is produced in exactly this one place on the api_server path, and the message explaining it never reached the pipe.

Solution: render the error preferring its stack, write it to stderr, and await the flush before exiting. One module-level helper in dev/src/cli/cli.ts, shared by both commands so the logic is not duplicated in each catch block:

async function exitOnStartupFailure(
  serverName: string,
  error: unknown,
): Promise<never> {
  const detail =
    error instanceof Error ? (error.stack ?? error.message) : String(error);
  // `process.exit()` discards pending asynchronous writes and writes to a pipe
  // are asynchronous on Windows, so wait for the flush callback before exiting.
  // The logger is bypassed for the same reason: its winston Console transport
  // defers the write by at least a tick, which `process.exit()` also outruns.
  await new Promise<void>((resolve) => {
    process.stderr.write(
      `[${CLI_LOG_LABEL}] Error starting ${serverName}: ${detail}\n`,
      () => resolve(),
    );
  });
  process.exit(1);
}

Notes on the shape:

  • Bypassing the logger here is deliberate, and is the point of the change: winston's transport defers the write past the process.exit() we are about to call. Every other logger.error call site in cli.ts is untouched.
  • write's callback fires when the chunk is flushed, including after backpressure drains, so an extra 'drain' listener would be redundant.
  • exitOnStartupFailure returns Promise<never>; the exit code stays 1, and the old as Error cast disappears rather than moving. The catch (error) bindings are left exactly as they were — this tsconfig resolves useUnknownInCatchVariables to true, so error is already unknown and an explicit annotation would be a no-op that dirties two otherwise untouched lines.
  • The 'ADK CLI' label is now one constant used by both the logger and the diagnostic, so the two cannot drift.
  • The flush is written inline rather than behind a flushStderr helper: it has exactly one caller, so the function boundary bought nothing the comment does not already say.
  • error instanceof Error is the repo's existing idiom for narrowing a caught value (10 sites in core/src, e.g. core/src/tools/function_tool.ts:166). The "no instanceof" rule targets ADK/SDK classes that can exist as two copies in one runtime; Error is a realm intrinsic.

Scope — this PR is deliberately one part of a larger plan, because two sibling PRs already land the rest. Stated explicitly so the omission is not read as an oversight:

Planned change Status
Harness: self-describing startProcess failures, OS-assigned ports, settle-once + timer cleanup, stop() awaits exit already landed by #546 (tests/integration/test_case_utils.ts, test_api_server.ts, go_server.ts) — CI-green on windows-latest
AdkApiServer: publish the bound port in A2A agent cards when --port 0 already landed by #300 (dev/src/server/adk_api_server.ts)
CLI: flush the start-up diagnostic to stderr before exiting this PR

Collision check (recorded as required): gh pr list --repo AmaadMartin/adk-js --state open --limit 1000 returned 489 open PRs. I ran gh pr diff --name-only over all 489 and filtered for dev/src/cli/cli.ts / dev/test/cli/cli_test.ts: 23 PRs touch them (#285, #289, #328, #333, #346, #358, #363, #385, #422, #433, #447, #448, #451, #455, #485, #511, #540, #547, #548, #550, #585, #586, #587). I then grepped every one of those diffs for added process.exit / stderr.write / Error starting … / flushStderr lines. None touches the web/api_server catch blocks. The nearest, #455, sets process.exitCode = 1 on the deploy commands. Separately, #546 and #300 (see the table above) land the harness and AdkApiServer halves; I did not reimplement either, and I did not stack on them because this change shares no file with either PR — branching from main keeps the diff conflict-free and lets the fork's pull_request: branches: [main] workflow actually run.

CI on this branch (fork, commit 42b2a631; the simplification commit d1dd33a0 re-runs it): run-tests (windows-latest) pass (9m13s), run-tests (macos-latest) pass, run-tests (ubuntu-latest) pass, run-tests (cross-language) pass, check-license pass.

The first attempt was red on macos-latest: tests/integration/app_loader/app_loader_test.ts > should discover apps vs agents across directories and standalone files timed out at 40000 ms. That test is nowhere near this diff (this PR touches only dev/src/cli/cli.ts and dev/test/cli/cli_test.ts), it is a known intermittent timeout on the macOS/Windows runners with several open PRs against it, and ubuntu-latest was green on the same commit. Because the matrix has no fail-fast: false, that failure cancelled the windows-latest leg — which is the leg that matters here — so I re-ran the workflow rather than changing anything, and all three legs passed on the same commit.

Testing Plan

Please describe the tests that you ran to verify your changes. This is required for all PRs that are not small documentation or typo fixes.
Unit Tests:
[x] I have added or updated unit tests for my change.
[x] All unit tests pass locally.

Six new cases in dev/test/cli/cli_test.ts (24 → 30).

A third commit applies the complexity review: flushStderr is inlined into its single caller, and the two redundant catch (error: unknown) annotations are reverted so those lines leave the diff entirely (net -13 lines in cli.ts). All seven mutations below were re-run against the restructured source and still fail; every command, number and coverage figure quoted here is from after that commit.

npx vitest run --project unit:dev dev/test/cli/cli_test.ts
  -> Test Files 1 passed (1); Tests 30 passed (30)

npx vitest run --project integration \
  tests/integration/a2a/basic/a2a_agent_test.ts tests/integration/adk_web/webui_test.ts
  -> Test Files 2 passed (2); Tests 3 passed (3)      (the suites that spawn this CLI)

npx eslint dev/src/cli/cli.ts dev/test/cli/cli_test.ts      -> clean
npx prettier --check dev/src/cli/cli.ts dev/test/cli/cli_test.ts -> all files use Prettier code style
npm run build                                               -> ok

npx tsc --noEmit (npm run ts:check) reports 2853 errors on main and 2853 with this change — none of them in either file this PR touches. That gate is pre-existing and is the subject of several other open PRs.

npx vitest run --project unit:dev dev/test/cli also reports one failure, cli_create_test.ts > should handle Vertex AI selection with gcloud defaults. It fails identically on a clean main (verified with git stash) — it is the known ambient-GOOGLE_CLOUD_* hermeticity bug, in a file this PR does not touch.

Prove each test can fail. Each mutation was applied to the fixed source, the suite run, the mutation reverted; the suite is green again afterwards. Run one at a time.

# Mutation Test(s) that failed Failure
1 Restore the original api_server catch (logger.error(...) + bare process.exit(1)) 4 cases AssertionError: expected '' to contain '[ADK CLI] Error starting API server: '
2 Restore the original web catch should write the web server failure and its stack to stderr AssertionError: expected '' to contain '[ADK CLI] Error starting web server: '
3 void new Promise(...) instead of await new Promise(...) around the write should exit only once the stderr diagnostic has flushed AssertionError: expected "spy" to not be called at all, but actually been called 1 times
4 Report error.message instead of error.stack both stack cases AssertionError: expected '[ADK CLI] Error starting API server: …' to contain 'Error: Port 41234 is already in use\n…'
5 Drop the non-Error branch ((error as Error).stack ?? (error as Error).message) should report a rejection value that is not an Error AssertionError: expected '…API server: …' to contain '…API server: the agent directory does not exist'
6 Drop the stack-less fallback (error.stack ?? '') should fall back to the message when the error carries no stack AssertionError: expected '…API server: ' to contain '…API server: Port 41234 is already in use'
7 port: parseInt(options['port'], 10) || 8000 should forward --port 0 to AdkApiServer unchanged AssertionError: expected 8000 to be +0

Mutation 3 is the one that pins the actual Windows fix: with a withheld flush callback the test asserts process.exit has not been called yet, so a fire-and-forget write fails it. Mutations 1 and 2 pin that the diagnostic reaches stderr at all (on main it goes to stdout through winston, so the capture is empty).

Coverage. dev/src/cli/cli.ts measured with --coverage.include='dev/src/cli/cli.ts' over this test file: 95.32% → 96.23% statements, 73.17% → 78.00% branches. Every statement and branch of the new code (lines 195-222) is executed — verified against coverage-final.json, not just the summary. The two lines v8 still reports uncovered in the changed region are the } after await exitOnStartupFailure(...) in each catch block: the helper returns Promise<never>, so the continuation is unreachable by construction, in tests and in production alike. That is a synthetic-branch artifact of the return type, and I did not restructure the code (e.g. by having the helper return normally) to make the number move.

No new suppressions. git diff main -U0 | grep -E '@ts-expect-error|@ts-ignore|eslint-disable|as any|as never|as unknown as|: any' returns nothing. The process.exit stub is typed without a cast by throwing (a function that only throws infers never), which also stops the test continuing past a point the real process never returns from. Injecting a start() rejection is done through one hoisted mock (second commit) instead of replacing the mocked constructor per test, which removes the as unknown as Mock the first draft needed; all existing assertions on instance.start are unchanged and still pass.

Manual End-to-End (E2E) Tests:
Please provide instructions on how to manually test your changes, including any necessary setup or configuration.

npm install && npm run build

# terminal 1 - hold a port
node -e "require('node:net').createServer().listen(41234,'localhost',()=>console.log('HELD'))"

# terminal 2 - point the CLI at it, separating the two streams
node dev/dist/esm/cli_entrypoint.js api_server tests/integration/adk_web/agent --port 41234 \
  >/tmp/out.txt 2>/tmp/err.txt; echo "exit=$?"

Before (main) — exit 1; /tmp/err.txt empty, /tmp/out.txt:

[ADK CLI] Error starting API server: Port 41234 is already in use

After (this branch) — exit 1; /tmp/out.txt empty, /tmp/err.txt:

[ADK CLI] Error starting API server: Error: Port 41234 is already in use
    at Server.<anonymous> (file:///<repo>/dev/dist/esm/server/adk_api_server.js:830:25)
    at Server.emit (node:events:519:28)
    at emitErrorNT (node:net:1970:8)
    at process.processTicksAndRejections (node:internal/process/task_queues:89:21)

The same holds for web ([ADK CLI] Error starting web server: …). The happy path is unchanged — api_server … --port 0 still prints the ADK API Server started banner with the bound port on stdout, which is what the integration harness matches on.

Windows caveat, stated plainly. The dropped-write behaviour this fixes is Windows-specific and cannot be reproduced on a Linux host: locally, both before and after, the text arrives. What is verified locally is everything that is verifiable here — the diagnostic now goes to stderr rather than stdout, carries the stack, and the process does not exit until the write has flushed (mutation 3). The Windows claim rests on Node's documented process.exit() and pipe-write semantics, plus the windows-latest CI leg on this branch.

Checklist

[x] I have read the CONTRIBUTING.md document.
[x] I have performed a self-review of my own code.
[x] I have commented my code, particularly in hard-to-understand areas.
[x] I have added tests that prove my fix is effective or that my feature works.
[x] New and existing unit tests pass locally with my changes.

Amaad Martin added 3 commits August 3, 2026 13:54
`adk web` and `adk api_server` logged a start-up failure through winston and
then called `process.exit(1)` in the same synchronous block. `process.exit()`
discards pending asynchronous writes and writes to a pipe are asynchronous on
Windows, so the only explanation of the failure was routinely dropped there --
which is why a spawned server that dies during start-up reports nothing but its
exit code in CI. The record also went to stdout rather than stderr, and only
carried `.message`, so a bundling failure lost its location.

Both catch blocks now render the error (preferring its stack) and await the
stderr write before exiting. The exit code stays 1.
… tests

Reach AdkApiServer.start() through one hoisted mock instead of replacing the
constructor per test, so injecting a rejection needs no `as unknown as Mock`.
Existing assertions on the instance's start() are unaffected.
flushStderr had one caller, so the named indirection bought nothing that the
comment does not already say; fold it into exitOnStartupFailure. Also drop the
`: unknown` annotations on the two catch bindings -- the tsconfig resolves
useUnknownInCatchVariables to true, so they were no-ops that made two otherwise
untouched lines part of the diff.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant