UAT: structlog debug logs written to stdout by default — pollutes JSON/YAML CLI output and breaks programmatic parsing #1958

Open
opened 2026-04-03 00:23:51 +00:00 by freemo · 3 comments
Owner

Metadata

  • Branch: fix/structlog-stdout-pollution-json-yaml-output
  • Commit Message: fix(logging): redirect structlog default output from stdout to stderr to prevent JSON/YAML CLI pollution
  • Milestone: v3.6.0
  • Parent Epic: #945

Background and Context

When configure_structlog() is not called (see related issue #1883), structlog uses its default configuration which writes log output to stdout instead of stderr. This causes debug log messages from the plugin manager and other components to be mixed into the stdout stream, making JSON/YAML output from --format json and --format yaml unparseable by programmatic consumers.

The specification (§Observability, §Structured Logging, §CLI Output) explicitly states:

  • core.log.terminal-stream defaults to stderr — log output must go to stderr, not stdout
  • Normal program output goes to stdout; log output goes to stderr
  • JSON/YAML output must be parseable without filtering log lines
  • "Increased verbosity writes to both the log file and stderr by default, keeping log output separate from normal program output on stdout."

This is distinct from #1883 (which focuses on secrets masking not being installed). This issue focuses on the stdout pollution caused by structlog's default PrintLogger writing to stdout instead of stderr.

Current Behavior

When configure_structlog() is not called, structlog's default PrintLogger writes all log output to stdout. Running any config command with --format json produces mixed output on stdout:

Steps to Reproduce:

# Run any config command with JSON format
uv run agents config get core.log.level --format json

Actual Output (stdout contains both debug logs AND JSON):

2026-04-02 23:52:12 [debug    ] plugin_manager.extension_point_registered name=context.strategy service=plugin_manager
2026-04-02 23:52:12 [debug    ] plugin_manager.extension_point_registered name=context.pipeline_component.strategy_selector service=plugin_manager
... (28 more debug lines)
{
  "key": "core.log.level",
  "value": "DEBUG",
  "source": "global",
  "type": "str"
}

Verification script:

import structlog, sys, io

# Capture stdout and stderr
old_stdout, old_stderr = sys.stdout, sys.stderr
sys.stdout = io.StringIO()
sys.stderr = io.StringIO()

logger = structlog.get_logger('test')
logger.debug('test message', key='value')

stdout_content = sys.stdout.getvalue()
stderr_content = sys.stderr.getvalue()
sys.stdout, sys.stderr = old_stdout, old_stderr

print('Stdout content:', repr(stdout_content))  # Contains debug log — WRONG
print('Stderr content:', repr(stderr_content))  # Empty — WRONG

Expected Behavior

Per the specification:

  • All log output (debug, info, warning, error) must be written to stderr, not stdout
  • --format json and --format yaml output on stdout must contain only the structured data payload — no log lines
  • CI/CD pipelines and scripts that parse JSON output must receive clean, parseable JSON

Root Cause

structlog's default configuration (when configure_structlog() is not called) uses PrintLogger which writes to stdout. The configure_structlog() function in src/cleveragents/config/logging.py would configure structlog to use the stdlib logging system (which defaults to stderr), but it is never called during CLI startup. This issue is a direct consequence of the missing startup call tracked in #1883, but represents a distinct, independently-verifiable symptom with its own acceptance criteria.

Impact

  • High: All JSON/YAML CLI output is polluted with debug log lines, making programmatic parsing fail
  • Affects all --format json and --format yaml commands
  • CI/CD pipelines and scripts that parse JSON output will fail silently or with parse errors

Affected Code Locations

  • src/cleveragents/config/logging.pyconfigure_structlog() function (never called; would configure stderr output)
  • src/cleveragents/infrastructure/plugins/manager.py — plugin_manager debug logging (emits 28+ debug lines to stdout on startup)
  • src/cleveragents/__main__.py — application entry point, does not call configure_structlog()

Subtasks

  • Ensure configure_structlog() is called at application startup (coordinate with #1883 fix)
  • Verify structlog is configured to write to stderr (not stdout) by default, matching core.log.terminal-stream spec default
  • Verify --format json output on stdout contains no log lines (only the JSON payload)
  • Verify --format yaml output on stdout contains no log lines (only the YAML payload)
  • Add BDD test scenario: JSON output is parseable when debug logging is active
  • Add BDD test scenario: log output goes to stderr, not stdout
  • Add integration test: capture stdout/stderr separately and assert clean JSON on stdout
  • Verify coverage >= 97% via nox -s coverage_report
  • Run nox (all default sessions), fix any errors

Definition of Done

This issue is complete when:

  • Log output (all levels) is written to stderr, not stdout, when structlog is configured per spec
  • uv run agents config get core.log.level --format json produces clean, parseable JSON on stdout with zero log lines
  • uv run agents config get core.log.level --format yaml produces clean, parseable YAML on stdout with zero log lines
  • BDD scenarios confirm stdout/stderr separation for all output formats
  • Integration test confirms programmatic JSON parsing succeeds when debug logging is active
  • All nox stages pass
  • Coverage >= 97%
  • A Git commit is created where the first line of the commit message matches the Commit Message in Metadata exactly, followed by a blank line, then additional lines providing relevant details about the implementation.
  • The commit is pushed to the remote on the branch matching the Branch in Metadata exactly.
  • The commit is submitted as a pull request to master, reviewed, and merged before this issue is marked done.

Automated by CleverAgents Bot
Supervisor: UAT Testing | Agent: ca-uat-tester

## Metadata - **Branch**: `fix/structlog-stdout-pollution-json-yaml-output` - **Commit Message**: `fix(logging): redirect structlog default output from stdout to stderr to prevent JSON/YAML CLI pollution` - **Milestone**: v3.6.0 - **Parent Epic**: #945 ## Background and Context When `configure_structlog()` is not called (see related issue #1883), structlog uses its default configuration which writes log output to **stdout** instead of **stderr**. This causes debug log messages from the plugin manager and other components to be mixed into the stdout stream, making JSON/YAML output from `--format json` and `--format yaml` unparseable by programmatic consumers. The specification (§Observability, §Structured Logging, §CLI Output) explicitly states: - `core.log.terminal-stream` defaults to `stderr` — log output must go to stderr, not stdout - Normal program output goes to stdout; log output goes to stderr - JSON/YAML output must be parseable without filtering log lines - "Increased verbosity writes to both the log file and stderr by default, keeping log output separate from normal program output on stdout." This is distinct from #1883 (which focuses on secrets masking not being installed). This issue focuses on the **stdout pollution** caused by structlog's default `PrintLogger` writing to stdout instead of stderr. ## Current Behavior When `configure_structlog()` is not called, structlog's default `PrintLogger` writes all log output to **stdout**. Running any config command with `--format json` produces mixed output on stdout: **Steps to Reproduce:** ```bash # Run any config command with JSON format uv run agents config get core.log.level --format json ``` **Actual Output (stdout contains both debug logs AND JSON):** ``` 2026-04-02 23:52:12 [debug ] plugin_manager.extension_point_registered name=context.strategy service=plugin_manager 2026-04-02 23:52:12 [debug ] plugin_manager.extension_point_registered name=context.pipeline_component.strategy_selector service=plugin_manager ... (28 more debug lines) { "key": "core.log.level", "value": "DEBUG", "source": "global", "type": "str" } ``` **Verification script:** ```python import structlog, sys, io # Capture stdout and stderr old_stdout, old_stderr = sys.stdout, sys.stderr sys.stdout = io.StringIO() sys.stderr = io.StringIO() logger = structlog.get_logger('test') logger.debug('test message', key='value') stdout_content = sys.stdout.getvalue() stderr_content = sys.stderr.getvalue() sys.stdout, sys.stderr = old_stdout, old_stderr print('Stdout content:', repr(stdout_content)) # Contains debug log — WRONG print('Stderr content:', repr(stderr_content)) # Empty — WRONG ``` ## Expected Behavior Per the specification: - All log output (debug, info, warning, error) must be written to **stderr**, not stdout - `--format json` and `--format yaml` output on stdout must contain **only** the structured data payload — no log lines - CI/CD pipelines and scripts that parse JSON output must receive clean, parseable JSON ## Root Cause structlog's default configuration (when `configure_structlog()` is not called) uses `PrintLogger` which writes to stdout. The `configure_structlog()` function in `src/cleveragents/config/logging.py` would configure structlog to use the stdlib logging system (which defaults to stderr), but it is never called during CLI startup. This issue is a direct consequence of the missing startup call tracked in #1883, but represents a distinct, independently-verifiable symptom with its own acceptance criteria. ## Impact - **High**: All JSON/YAML CLI output is polluted with debug log lines, making programmatic parsing fail - Affects all `--format json` and `--format yaml` commands - CI/CD pipelines and scripts that parse JSON output will fail silently or with parse errors ## Affected Code Locations - `src/cleveragents/config/logging.py` — `configure_structlog()` function (never called; would configure stderr output) - `src/cleveragents/infrastructure/plugins/manager.py` — plugin_manager debug logging (emits 28+ debug lines to stdout on startup) - `src/cleveragents/__main__.py` — application entry point, does not call `configure_structlog()` ## Subtasks - [ ] Ensure `configure_structlog()` is called at application startup (coordinate with #1883 fix) - [ ] Verify structlog is configured to write to `stderr` (not `stdout`) by default, matching `core.log.terminal-stream` spec default - [ ] Verify `--format json` output on stdout contains no log lines (only the JSON payload) - [ ] Verify `--format yaml` output on stdout contains no log lines (only the YAML payload) - [ ] Add BDD test scenario: JSON output is parseable when debug logging is active - [ ] Add BDD test scenario: log output goes to stderr, not stdout - [ ] Add integration test: capture stdout/stderr separately and assert clean JSON on stdout - [ ] Verify coverage >= 97% via `nox -s coverage_report` - [ ] Run `nox` (all default sessions), fix any errors ## Definition of Done This issue is complete when: - [ ] Log output (all levels) is written to stderr, not stdout, when structlog is configured per spec - [ ] `uv run agents config get core.log.level --format json` produces clean, parseable JSON on stdout with zero log lines - [ ] `uv run agents config get core.log.level --format yaml` produces clean, parseable YAML on stdout with zero log lines - [ ] BDD scenarios confirm stdout/stderr separation for all output formats - [ ] Integration test confirms programmatic JSON parsing succeeds when debug logging is active - [ ] All nox stages pass - [ ] Coverage >= 97% - [ ] A Git commit is created where the **first line** of the commit message matches the Commit Message in Metadata exactly, followed by a blank line, then additional lines providing relevant details about the implementation. - [ ] The commit is pushed to the remote on the branch matching the **Branch** in Metadata exactly. - [ ] The commit is submitted as a **pull request** to `master`, reviewed, and **merged** before this issue is marked done. --- **Automated by CleverAgents Bot** Supervisor: UAT Testing | Agent: ca-uat-tester
freemo added this to the v3.6.0 milestone 2026-04-03 00:24:17 +00:00
Author
Owner

Issue triaged by project owner:

  • State: Verified
  • MoSCoW: MoSCoW/Should Have — bug or error handling improvement.

Automated by CleverAgents Bot
Supervisor: Project Owner | Agent: ca-project-owner

Issue triaged by project owner: - **State**: Verified - **MoSCoW**: MoSCoW/Should Have — bug or error handling improvement. --- **Automated by CleverAgents Bot** Supervisor: Project Owner | Agent: ca-project-owner
Author
Owner

Issue triaged by project owner:

  • State: Verified
  • Priority: High — structlog writing debug logs to stdout breaks all JSON/YAML CLI output parsing, affecting CI/CD pipelines and programmatic consumers. This is a spec violation (core.log.terminal-stream defaults to stderr).
  • Milestone: v3.6.0 (already assigned, correct — this is an M7 Advanced Concepts concern related to observability and logging infrastructure)
  • MoSCoW: Should Have — the spec explicitly requires log output on stderr. While not a blocker for core functionality, it breaks programmatic CLI usage which is important for the v3.6.0 milestone's E2E workflow specification tests.
  • Parent Epic: #945 (as noted in the issue metadata)

The issue is well-documented with clear reproduction steps, spec references, and a thorough root cause analysis. Valid and actionable.


Automated by CleverAgents Bot
Supervisor: Project Owner | Agent: ca-project-owner

Issue triaged by project owner: - **State**: Verified - **Priority**: High — structlog writing debug logs to stdout breaks all JSON/YAML CLI output parsing, affecting CI/CD pipelines and programmatic consumers. This is a spec violation (`core.log.terminal-stream` defaults to `stderr`). - **Milestone**: v3.6.0 (already assigned, correct — this is an M7 Advanced Concepts concern related to observability and logging infrastructure) - **MoSCoW**: Should Have — the spec explicitly requires log output on stderr. While not a blocker for core functionality, it breaks programmatic CLI usage which is important for the v3.6.0 milestone's E2E workflow specification tests. - **Parent Epic**: #945 (as noted in the issue metadata) The issue is well-documented with clear reproduction steps, spec references, and a thorough root cause analysis. Valid and actionable. --- **Automated by CleverAgents Bot** Supervisor: Project Owner | Agent: ca-project-owner
Author
Owner

Issue triaged by project owner:

  • State: Verified
  • Priority: High (unchanged)
  • Milestone: v3.6.0 (already assigned)
  • MoSCoW: Should Have — structlog debug logs polluting stdout breaks JSON/YAML CLI output parsing. The specification requires clean, parseable output formats. This is important for programmatic usage but not a showstopper for the milestone.

Automated by CleverAgents Bot
Supervisor: Project Owner | Agent: ca-project-owner

Issue triaged by project owner: - **State**: Verified ✅ - **Priority**: High (unchanged) - **Milestone**: v3.6.0 (already assigned) - **MoSCoW**: Should Have — structlog debug logs polluting stdout breaks JSON/YAML CLI output parsing. The specification requires clean, parseable output formats. This is important for programmatic usage but not a showstopper for the milestone. --- **Automated by CleverAgents Bot** Supervisor: Project Owner | Agent: ca-project-owner
freemo removed this from the v3.6.0 milestone 2026-04-07 01:31:37 +00:00
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Reference
cleveragents/cleveragents-core#1958
No description provided.