From 118756f995974000740c85c3b2e8731138bee4f2 Mon Sep 17 00:00:00 2001 From: Zongwei9888 Date: Fri, 7 Aug 2026 15:46:39 +0800 Subject: [PATCH] fix(cli): install log sinks at startup so internals stay off the terminal MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Reported in #167. loguru ships a stderr sink at DEBUG level and nothing on the CLI path ever replaced it — `setup_logging()` was defined, exported and documented, but never called. Confirmed by inspecting the handler table after importing the CLI: one sink, id 0, level 10. The visible symptom is the line `load_config` emits for each absent config layer, which is every directory without a project-level deepcode_config.json: DEBUG | core.config:_load_raw:580 - deepcode_config.json not found at /Users/.../deepcode_config.json; skipping layer The reporter also noted `LoggerConfig.level` had no consumer, so the config offered no way to change this. Both follow from the same missing call. Ordering is the awkward part, and the reason this is not one line: reading the config is itself something that logs. So a quiet default goes in first, and the configured level is applied afterwards only when it differs. DEEPCODE_LOG_LEVEL short-circuits both, needs no config file, and matches what `deepcode mcp` already honours — it is the escape hatch for debugging config loading itself. Placed in deepcode.main(), which is the sole console_scripts entry and dispatches all ten subcommands. The report suggested the TUI and loop entrypoints; putting it in each would be the same block copied ten times, and the eleventh subcommand would forget it. Verified from a directory with no project config: sink level moves 10 -> 20 and the DEBUG line stops, while DEEPCODE_LOG_LEVEL=DEBUG brings it back. Co-Authored-By: Claude Opus 5 (1M context) --- deepcode.py | 38 ++++++++++ tests/test_cli_logging_bootstrap.py | 108 ++++++++++++++++++++++++++++ 2 files changed, 146 insertions(+) create mode 100644 tests/test_cli_logging_bootstrap.py diff --git a/deepcode.py b/deepcode.py index b7317399..a6a1c87d 100755 --- a/deepcode.py +++ b/deepcode.py @@ -85,8 +85,46 @@ def launch_paper_test(paper_name: str, fast_mode: bool = False): sys.exit(1) +def _bootstrap_logging() -> None: + """Install log sinks before anything can log. + + Without this, loguru keeps its built-in stderr sink at DEBUG level, so + routine internals reach the terminal — most visibly the "config layer + absent" line that ``load_config`` emits in any directory without a + project-level ``deepcode_config.json`` (#167). + + Order matters and is the reason this is not simply + ``setup_logging(load_config().logger)``: reading the config is itself + one of the things that logs. So install a quiet default first, then + re-apply only if the user asked for something else. ``DEEPCODE_LOG_LEVEL`` + wins over both and needs no config file, matching ``deepcode mcp``. + + Every subcommand below is dispatched from here, so this is the one place + that has to remember — a per-entrypoint call would be the same four lines + repeated ten times, and the next subcommand would forget them. + """ + from core.config import LoggerConfig, load_config + from core.observability import setup_logging + + override = os.environ.get("DEEPCODE_LOG_LEVEL") + setup_logging(LoggerConfig(level=override or "INFO", transports=["console"])) + if override: + return + + try: + configured = load_config().logger + except Exception: + # A broken or unreadable config is the subcommand's problem to report + # properly; logging is already usable, so do not fail here. + return + if configured.level.upper() != "INFO": + setup_logging(configured, force=True) + + def main(): """Main function""" + _bootstrap_logging() + # Parse command line arguments if len(sys.argv) > 1: if sys.argv[1] in {"--version", "-V"}: diff --git a/tests/test_cli_logging_bootstrap.py b/tests/test_cli_logging_bootstrap.py new file mode 100644 index 00000000..817f6ae7 --- /dev/null +++ b/tests/test_cli_logging_bootstrap.py @@ -0,0 +1,108 @@ +"""The CLI installs its own log sinks before anything can log. + +Reported in #167: loguru ships a stderr sink at DEBUG level, and nothing on +the CLI path ever replaced it. Routine internals therefore reached the user's +terminal — most visibly the "config layer absent" line `load_config` emits in +any directory without a project-level `deepcode_config.json`. + +The ordering is the subtle part: reading the config is itself one of the +things that logs, so a quiet default has to be installed first. +""" + +from __future__ import annotations + +import sys +from pathlib import Path + +import pytest +from loguru import logger + +ROOT = Path(__file__).resolve().parents[1] +if str(ROOT) not in sys.path: + sys.path.insert(0, str(ROOT)) + +import deepcode # noqa: E402 +from core.observability import shutdown_logging # noqa: E402 + + +def sink_levels() -> list[int]: + return [handler.levelno for handler in logger._core.handlers.values()] # noqa: SLF001 + + +@pytest.fixture(autouse=True) +def _restore_logging(): + yield + shutdown_logging() + + +def test_bootstrap_replaces_the_default_debug_sink(monkeypatch, tmp_path): + monkeypatch.delenv("DEEPCODE_LOG_LEVEL", raising=False) + monkeypatch.setenv("DEEPCODE_HOME", str(tmp_path / "home")) + monkeypatch.chdir(tmp_path) + + deepcode._bootstrap_logging() + + # 10 is loguru's DEBUG. Leaving it in place is what put internals on the + # terminal; INFO (20) or quieter is the contract here. + assert sink_levels(), "bootstrap must leave at least one sink installed" + assert min(sink_levels()) >= 20 + + +def test_env_override_wins_without_any_config_file(monkeypatch, tmp_path): + """`DEEPCODE_LOG_LEVEL` has to work before a config exists — it is the + escape hatch for debugging config loading itself.""" + + monkeypatch.setenv("DEEPCODE_LOG_LEVEL", "DEBUG") + monkeypatch.setenv("DEEPCODE_HOME", str(tmp_path / "home")) + monkeypatch.chdir(tmp_path) + + deepcode._bootstrap_logging() + + assert min(sink_levels()) <= 10 + + +def test_configured_level_is_honoured(monkeypatch, tmp_path): + """`logger.level` in the config had no consumer at all before this.""" + + home = tmp_path / "home" + home.mkdir() + (home / "deepcode_config.json").write_text( + '{"logger": {"level": "warning", "transports": ["console"]}}', + encoding="utf-8", + ) + monkeypatch.delenv("DEEPCODE_LOG_LEVEL", raising=False) + monkeypatch.setenv("DEEPCODE_HOME", str(home)) + monkeypatch.chdir(tmp_path) + + deepcode._bootstrap_logging() + + assert min(sink_levels()) >= 30 # WARNING + + +def test_an_unreadable_config_does_not_break_startup(monkeypatch, tmp_path): + """Logging must survive a broken config; reporting it is the + subcommand's job, and it needs working sinks to do that.""" + + home = tmp_path / "home" + home.mkdir() + (home / "deepcode_config.json").write_text("{ not json", encoding="utf-8") + monkeypatch.delenv("DEEPCODE_LOG_LEVEL", raising=False) + monkeypatch.setenv("DEEPCODE_HOME", str(home)) + monkeypatch.chdir(tmp_path) + + deepcode._bootstrap_logging() + + assert sink_levels() + + +def test_main_bootstraps_before_dispatching(monkeypatch, capsys): + """The call belongs in the one dispatcher every subcommand goes through, + not repeated in each entrypoint.""" + + called: list[bool] = [] + monkeypatch.setattr(deepcode, "_bootstrap_logging", lambda: called.append(True)) + monkeypatch.setattr(sys, "argv", ["deepcode", "--version"]) + + deepcode.main() + + assert called == [True]