Skip to content

analyse/* installs a stderr logging handler at import; routine INFO progress pollutes stderr (renders red under tox/CI) #72

@ubmarco

Description

@ubmarco

Summary

Used as a Sphinx extension, the analyse/ layer writes routine progress — Source files loaded: N, Source comments extracted: N, Oneline needs extracted: N — to stderr at INFO level, through a logging.StreamHandler the library installs on its own loggers at import time. Because the messages are on stderr, wrappers that colorize stderr (tox, many CI log viewers) render these harmless INFO lines red, where they read as errors — although the build succeeds (exit 0) and they are not warnings.

Environment

  • sphinx-codelinks 1.2.0; Sphinx 8.2.3; Python 3.12
  • Surfaced via tox 4.48.1, which renders subprocess stderr in red

Repro

Any project using sphinx_codelinks as an extension:

sphinx-build -b html -c docs docs/source /tmp/out 1>/tmp/out.log 2>/tmp/err.log
grep -nE "Source files loaded|comments extracted|Oneline needs extracted" /tmp/err.log

The lines appear only in the stderr capture; 2>/dev/null makes them vanish. Exit code is 0.

Root cause

Each analyse/ module configures logging and adds a handler at import scope:

# analyse/analyse.py:31-36  (same shape in utils.py:35-40, oneline_parser.py:8-13, projects.py:14-19)
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
console = logging.StreamHandler()   # no stream arg -> defaults to sys.stderr
console.setLevel(logging.INFO)
logger.addHandler(console)

Routine progress is then emitted at INFO (analyse.py:113-114, 359).

  1. Libraries shouldn't install handlers on their loggers. Per the stdlib logging guidance, a library should only getLogger(__name__) and emit; configuring handlers/levels/streams is the application's job. An import-time StreamHandler removes that choice from consumers and can't be undone without reaching into the library's logger.
  2. Routine progress goes to stderr. StreamHandler() defaults to sys.stderr, so informational output lands on the error stream and gets reddened by stderr-aware wrappers.

The Sphinx-extension submodules already do the right thing — sphinx_extension/source_tracing.py and sphinx_extension/directives/src_trace.py use from sphinx.util import logging, routing through Sphinx's logging (verbosity, suppress_warnings, color, stream routing). The analyse/ layer is inconsistent with that.

Suggested fix

  • Drop the import-time StreamHandler() + setLevel() + addHandler() from analyse/analyse.py, analyse/utils.py, analyse/oneline_parser.py, analyse/projects.py; keep only logger = logging.getLogger(__name__).
  • As a Sphinx extension, route progress through sphinx.util.logging (consistent with sphinx_extension/*). For the standalone CLI, send progress to stdout (or gate behind --verbose), reserving stderr for warnings/errors.

Related to #21 (separating CLI vs Sphinx-extension concerns).

Extra note (not a sphinx-codelinks bug)

With the furo theme these lines appear doubled — once bare, once as # <ts> INFO sphinx_codelinks.analyse.analyse analyse.py:113 -- .... The second copy comes from accessible-pygments, which calls logging.basicConfig() on the root logger at import; codelinks records propagate to it. That's a separate upstream issue, but it compounds the noise — and disappears once codelinks stops emitting INFO to stderr (or sets propagate=False).

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type
    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions