Skip to content

Fix: pin the ADK test log level inside the vitest workers - #557

Open
AmaadMartin wants to merge 2 commits into
mainfrom
fix/pin-adk-log-level-in-vitest-workers
Open

Fix: pin the ADK test log level inside the vitest workers#557
AmaadMartin wants to merge 2 commits into
mainfrom
fix/pin-adk-log-level-in-vitest-workers

Conversation

@AmaadMartin

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):
    N/A — no public issue is open for this.
  2. Or, if no issue exists, describe the change:

Problem: tests/global_setup.ts calls setLogLevel(LogLevel.ERROR) and vitest.config.ts wired it in as globalSetup, but the pin never reached the code under test. Every run still printed INFO: [ADK] ... / WARN: [ADK] ... from library code. Two independent reasons:

  1. Wrong process. Vitest runs globalSetup once in the main process, before any worker exists — "the global setup is running in a different global scope before test workers are even created", and "If you need to execute code in the same process as tests, use setupFiles instead" (https://vitest.dev/config/globalsetup). The level is module state (SimpleLogger.logLevel on the module-level currentLogger in core/src/utils/logger.ts), so mutating it in the main process leaves the worker's copy at its LogLevel.INFO default.
  2. Wrong module instance. Only the per-project alias maps @google/adk to core/src. From tests/, the bare specifier resolves through the workspace symlink to the built core/dist bundle — a second module instance with its own currentLogger.

Reason 2 is directly observable: on a tree that has not been built, the old wiring does not merely no-op, it aborts the run before collection:

Error: Failed to resolve entry for package "@google/adk".
6 |  import { LogLevel, setLogLevel } from "@google/adk";
  |                                         ^     (tests/global_setup.ts)

The winston instance filters nothing either: it is created with level: 'error' against the inverted table {debug: 0, info: 1, warn: 2, error: 3}, and winston keeps a record when levels[message] <= levels[configured] — true for all four. The if (this.logLevel > level) return; guards in SimpleLogger are the only gate, and it was wide open.

Solution: Move the pin to a setupFiles module, which Vitest evaluates inside each worker before the test file (https://vitest.dev/config/setupfiles), and import the logger by relative path so it is the same module instance the aliased tests use. tests/global_setup.ts is deleted and globalSetup removed.

The entry is repeated in all six project blocks because "None of the configuration options are inherited from the root-level config file" (https://vitest.dev/guide/projects) — a single root-level entry would be silently ignored.

The setup file deliberately does not import the @google/adk barrel: from tests/ that specifier reaches the built bundle rather than core/src (reason 2 above), which is the bug this change fixes.

Measured effect on unit:core + unit:dev + unit:integrations, same command before and after:

[ADK] lines INFO WARN ERROR
before 382 76 300 6
after 7 0 1 6

ERROR is unchanged at 6 — the change silences noise, it does not hide errors.

Honest residual — one WARN survives. It comes from core/test/tools/mcp/mcp_toolset_test.ts, which calls vi.resetModules() (line 14). That wipes the module registry, so the test's next import constructs a fresh SimpleLogger at the default INFO; the setup file already ran and pinned the previous instance, and its imported setLogLevel binding still refers to that old instance, so re-applying the pin could not reach the new one either. This is inherent to pinning module state and is not fixable from the setup file. I left it rather than modify a test that is not mine to change. So the spec's "no INFO/WARN lines" postcondition holds for 381 of 382 lines, not 382 — stating the measured number rather than the intended one.

Deliberate scope deviation (1). The plan sketched an afterAll(() => setLogLevel(LogLevel.INFO)) restore in the setup file. I omitted it. Its stated justification is isolate: false, and this repo does not set isolate, so it defaults to true: every test file gets a fresh module registry, the setup file re-runs per file, and the hook would restore a level nothing subsequently reads — dead code. Under isolate: false it would be actively worse, opening a window between one file's afterAll and the next file's setup in which logging is un-pinned. Happy to add it if a reviewer disagrees.

Prior-art / collision check (gh pr list --repo AmaadMartin/adk-js --state open --limit 1000, 456 open PRs scanned): #349 implements the same fix. It is stacked on the unmerged fix/hermetic-unit-test-env (#302), so its setupFiles hunks assume a tests/hermetic_env_setup.ts that does not exist on main and will not apply there. This PR is the main-based equivalent and is independently portable. If #302 and #349 land first, close this one; if they do not, this one stands alone. Neither #431 (getLogLevel() accessor) nor #432 (shared level-gated winston logger) is depended on here. No equivalent PR exists upstream.

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.

core/test/utils/log_level_pin_test.ts asserts the pin through the public API (getLogger() from @google/adk). There is no public accessor for the effective level, and reading private state (getLogger()['logLevel']) or widening the member for a test are both out, so the probe asserts on what the logger writes: it swaps globalThis.console for a node:console Console bound to an in-memory node:stream Writable, restored in a finally. That shape is required because winston's Console transport writes to console._stdout/console._stderr of whatever globalThis.console is at log time — Vitest installs its own Console in the worker, so vi.spyOn(process.stdout, 'write') and vi.spyOn(console, 'log') both capture nothing. The write is synchronous, so no await/waitFor is needed.

Two cases, and the second is load-bearing: error still emitting proves the harness captures at all, so the info case cannot pass vacuously.

Proof the test can fail. Two mutations, both confirmed:

Mutation 1 — the original bug (old globalSetup wiring, no setupFiles). The probe was written and run before the fix:

 × test worker log level > suppresses info logs 10ms
 ✓ test worker log level > still emits error logs 1ms

AssertionError: expected '\u001b[32mINFO\u001b[39m: [ADK] 2026-…' to be '' // Object.is equality
+ INFO: [ADK] 2026-08-03T02:41:11.275Z info-pin-probe

Mutation 2 — fix applied, setupFiles removed from the unit:core block only:

 × test worker log level > suppresses info logs 9ms
 ✓ test worker log level > still emits error logs 1ms
AssertionError: expected '\u001b[32mINFO\u001b[39m: [ADK] 2026-…' to be '' // Object.is equality
      Tests  1 failed | 1 passed (2)

With the change applied, both pass: Tests 2 passed (2).

No fallout. npx vitest run --project unit:core --project unit:dev --project unit:integrations, run on this branch and on the pristine base for comparison:

test files tests
base 3 failed / 180 passed 5 failed / 2570 passed
this branch 3 failed / 181 passed 5 failed / 2572 passed

The same 5 failures occur on both — unsafe_local_code_executor_test.ts (×3), cli_create_test.ts, integrations/version_test.ts. They are pre-existing on this base and unrelated to logging; this branch adds the 2 passing probe tests and changes nothing else. Tests that assert on logging do so by spying the logger object or installing a custom Logger, both of which bypass the level gate, so they are unaffected.

npx tsc --noEmit reports 281 errors on the pristine base and the identical 281 with this change (diffed error-for-error by file/line/code: no delta). They are pre-existing dual-module-instance errors on this base; neither new file appears among them. npm run lint passes (exit 0). npm run format:check passes. npm run build passes.

No suppressions of any kind are added: git diff <base> -U0 | grep -E '@ts-expect-error|@ts-ignore|eslint-disable|as any|: any\b|v8 ignore' returns nothing.

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

  1. npm install && npm run build
  2. npx vitest run --project unit:core 2>&1 | grep -c '\[ADK\]' — counts ADK log lines. On main this is dominated by INFO/WARN; with this change only ERROR lines remain. (Grep for [ADK], not INFO: [ADK]: the level is ANSI-colorized, so INFO: is not literally contiguous in the output.)
  3. npx vitest run --project unit:core core/test/utils/log_level_pin_test.ts — 2 passed.
  4. Remove './tests/setup_log_level.ts' from the unit:core block and re-run step 3 — the info case fails. Restore it.
  5. ls tests/global_setup.ts — gone; the only remaining globalSetup mentions in the repo are explanatory comments, not wiring.

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 2 commits August 2, 2026 19:46
vitest runs globalSetup once in the main process, before any worker
exists, so the setLogLevel(ERROR) call in tests/global_setup.ts could
never reach the code under test: the level is module state on the
logger's currentLogger instance, which a worker does not inherit.

The bare '@google/adk' specifier in that file compounded it. Only the
per-project alias maps that specifier to core/src; from tests/ it
resolves through the workspace symlink to the built core/dist bundle,
a second module instance with its own level -- and one that has to be
built before any unit test can start.

Move the pin to a setupFiles module, which vitest evaluates inside each
worker before the test file, and import the logger module by relative
path so it is the same instance the aliased tests use. Every project
block gets the entry: projects inherit nothing from the root config.

https://vitest.dev/config/globalsetup
https://vitest.dev/config/setupfiles
The pin had no observing test, which is why it sat broken. There is no
public accessor for the effective level, so the probe asserts on what
the logger writes instead of reading private state: it swaps in a
Console bound to an in-memory stream, since the winston Console
transport writes to whatever globalThis.console is at log time.

The error case is load-bearing -- it proves the capture harness works,
so the info case cannot pass vacuously.
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