Skip to content

Fix: route core logger warn and error records to stderr - #697

Open
AmaadMartin wants to merge 1 commit into
mainfrom
fix/logger-errors-to-stderr
Open

Fix: route core logger warn and error records to stderr#697
AmaadMartin wants to merge 1 commit into
mainfrom
fix/logger-errors-to-stderr

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):
    Closes: #issue_number
    Related: #issue_number
  2. Or, if no issue exists, describe the change:
    Problem: The core ADK logger writes every level to stdout, including warn and error. Winston's Console transport only routes a record to stderr when the level is listed in the transport's stderrLevels option, and SimpleLogger constructed the transport with no options. So 2>/dev/null cannot suppress ADK diagnostics, and a pipe on stdout swallows them.

Solution: I pass stderrLevels: ['warn', 'error'] to the Console transport. info and debug stay on stdout, because the bug is about diagnostics only. This matches the POSIX stream contract and adk-python, where logging.basicConfig installs a StreamHandler that defaults to sys.stderr.

Scope: this change covers core only. The dev package needs the same one-line change, and open fork PR #672 ("Fix: route AdkLogger warn and error records to stderr") already makes it in dev/src/utils/logger.ts. I did not duplicate it. The two changes touch disjoint files, so this branch is based on main rather than stacked on #672.

Collision check. I listed all 594 open PRs on the fork and diffed every plausibly adjacent one. #672 covers dev (see above). #683 moves the core winston logger into core/src/utils/logger_node.ts and #432 deduplicates both loggers; neither adds stderrLevels, so neither fixes this bug. Both restructure the code around the line I change, so expect a small merge conflict if they land first.

Intentional behaviour change. A consumer that pipes ADK stdout into a log collector stops seeing warn and error lines there and must also collect stderr. No API, type, export or message-format changes, so this is not a breaking change in the semver sense.

Verified observation, not fixed here. Every level method calls messages.join(' '). An Error renders as "Error: boom" and loses its .stack; a plain object becomes "[object Object]". This matters because dev/src/server/adk_api_server.ts passes a caught unknown straight to this.logger.error(error) in about 20 places. That is a separate defect and out of scope here.

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.

I added a new describe('SimpleLogger console transport') block to core/test/utils/logger_test.ts. The existing describe('setLogger') block is untouched. Six new tests: error and warn reach stderr and not stdout; info and debug reach stdout and not stderr; the stderr record keeps its upper-cased ERROR token; a record below the log level reaches neither stream.

Winston writes to console._stdout / console._stderr directly, so a console.error spy never sees a record. Each test installs a Console built on two capture streams instead. That helper is local to this file. PR #672 has an equivalent helper in dev/test, because there is no precedent for dev/test importing from core/test and ten shared lines do not justify inventing one.

npx vitest run --project unit:core core/test/utils/logger_test.ts     -> 14 passed (8 pre-existing + 6 new)
npx vitest run --project unit:core core/test/plugins/logging_plugin_test.ts -> 29 passed
npm run build        -> OK
npm run lint         -> OK (eslint on both changed files)
npm run format:check -> OK
npm run docs:check   -> OK
bash scripts/check_license.sh -> OK

Coverage of the changed lines is 100%, measured with --coverage.include='core/src/utils/logger.ts'. The remaining uncovered lines in that file are pre-existing NoOpLogger methods and level-gating early returns.

npm run ts:check reports 280 errors, but it reports the same 280 errors on a clean main in my environment, and the two lists are byte-identical. None of them is in a file I touched. The cause is that BASE_AGENT_SIGNATURE_SYMBOL is emitted as a non-exported unique symbol in core/dist/types, so @google/adk and core/src disagree about its identity. That is pre-existing and unrelated.

Proof the tests can fail. I ran the new tests against three mutations of the source line.

Mutation Result
new winston.transports.Console() (the bug) 4 failed, 10 passed. First failure: AssertionError: expected '' to contain 'boom'
stderrLevels: ['error'] 1 failed, 13 passed. AssertionError: expected '' to contain 'careful'
stderrLevels: ['WARN', 'ERROR'] 4 failed, 10 passed. AssertionError: expected '' to contain 'boom'

The third mutation matters most. Winston matches stderrLevels against info[LEVEL], the raw lowercase level, while the format uppercases info.level for display. Upper-cased names therefore match nothing, and the suite catches it.

Integration test:

npx vitest run --project integration tests/integration/app_loader/app_loader_test.ts -> 6 passed

This suite first failed for me with Error: Hook timed out in 40000ms. Its beforeAll runs npm install in a fixture directory against a 40s budget, and a cold install exceeds that behind my proxy. The suite's afterAll deletes the fixture's node_modules only on a passing run, so runs alternate cold and warm. With the fixture warm it passes with my change applied. The failure is environmental and has no path to the logger.

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

npm run build
E='const {getLogger}=require("./core/dist/cjs/index.js");'
node -e "$E getLogger().error('boom')"   2>/dev/null   # prints nothing
node -e "$E getLogger().error('boom')"   1>/dev/null   # prints ERROR: [ADK] ... boom
node -e "$E getLogger().warn('careful')" 2>/dev/null   # prints nothing
node -e "$E getLogger().warn('careful')" 1>/dev/null   # prints WARN: [ADK] ... careful
node -e "$E getLogger().info('hello')"   1>/dev/null   # prints nothing
node -e "$E getLogger().info('hello')"   2>/dev/null   # prints INFO: [ADK] ... hello

I confirmed the contrast. Before the change, run 1 printed the error and run 2 printed nothing. Use getLogger(), not a logger binding: core/src/common.ts:283 exports getLogger, setLogger, setLogLevel and LogLevel, and no logger.

I also checked that the API server readiness banner stays on stdout, because tests/integration/test_api_server.ts:49 matches it there:

node dev/dist/esm/cli_entrypoint.js api_server tests/integration/agents --port 8129 2>/dev/null
#  -> the "| ADK API Server started |" box IS printed
node dev/dist/esm/cli_entrypoint.js api_server tests/integration/agents --port 8130 1>/dev/null
#  -> nothing on stderr (0 bytes)

The banner is a plain console.log at dev/src/server/adk_api_server.ts:963, so no transport option can move it. I confirmed two further preconditions by grep: no test in core/test, dev/test or tests/ spies on console._stdout, console._stderr, process.stdout.write or process.stderr.write to observe logger output, and core/test contains no spyOn(console, ...) at all.

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.

Winston's Console transport writes every level to stdout unless it is
given stderrLevels, so 2>/dev/null could not suppress ADK diagnostics and
a pipe on stdout swallowed them. Diagnostics now follow the POSIX stream
contract, which also matches adk-python.

The dev package needs the same one-line change. Fork PR #672 already
makes it, so this change stays inside core to avoid a duplicate.
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