Add opt-in debug logging across the CLI pipeline

Thread RP_DEBUG-driven logging through input, detection, rendering, and pager decisions so CLI behavior is inspectable without polluting stdout. Add focused coverage for debug wiring, env parsing, and stderr-only output.
This commit is contained in:
2026-04-03 19:09:24 -07:00
parent 37502c3083
commit 93c777cf6a
10 changed files with 296 additions and 11 deletions

View File

@@ -10,6 +10,7 @@ import typer
from rich.console import Console
from rp import __author__, __license__, __version__
from rp.debug import env_debug_enabled, log_debug, make_debug_logger
from rp.detect import detect_type
from rp.render import RenderOptions, render
@@ -95,13 +96,16 @@ def main(
version: Show version and exit.
"""
console = Console()
debug = make_debug_logger(Console(stderr=True), env_debug_enabled())
if file is None or str(file) == "-":
log_debug(debug, "input: reading from stdin")
if sys.stdin.isatty():
console.print("[dim]Reading from stdin. Press Ctrl+D to end.[/dim]")
content = sys.stdin.read()
file_path = None
else:
log_debug(debug, f"input: reading file {str(file)!r}")
if not file.exists():
console.print(f"[red]Error:[/red] File not found: {file}")
raise typer.Exit(code=1)
@@ -127,12 +131,14 @@ def main(
content=content,
explicit_type=file_type,
guess_content=guess_content,
debug=debug,
)
options = RenderOptions(
theme=theme,
line_numbers=line_numbers,
pager=pager,
debug=debug,
)
render(content, file_type, console, options)

40
src/rp/debug.py Normal file
View File

@@ -0,0 +1,40 @@
"""Debug logging helpers for rp."""
from __future__ import annotations
import os
from collections.abc import Callable, Mapping
from rich.console import Console
from rich.text import Text
DEBUG_ENV_VAR = "RP_DEBUG"
_FALSE_DEBUG_VALUES = {"", "0", "false", "no", "off"}
type DebugLogger = Callable[[str], None]
def env_debug_enabled(env: Mapping[str, str] | None = None) -> bool:
"""Return whether debug logging is enabled via ``RP_DEBUG``."""
source = os.environ if env is None else env
value = source.get(DEBUG_ENV_VAR)
if value is None:
return False
return value.strip().lower() not in _FALSE_DEBUG_VALUES
def make_debug_logger(console: Console, enabled: bool) -> DebugLogger | None:
"""Return a console-backed debug logger when debug mode is enabled."""
if not enabled:
return None
def _log(message: str) -> None:
console.print(Text.assemble(("[rp debug] ", "dim"), message))
return _log
def log_debug(debug: DebugLogger | None, message: str) -> None:
"""Emit a debug line when a debug logger is configured."""
if debug is not None:
debug(message)

View File

@@ -10,6 +10,8 @@ from pathlib import Path
from pygments.lexers import guess_lexer
from pygments.util import ClassNotFound
from rp.debug import DebugLogger, log_debug
EXTENSION_MAP: dict[str, str] = {
".md": "markdown",
".json": "json",
@@ -182,11 +184,15 @@ def _detect_shebang(content: str) -> str | None:
return _SHEBANG_MAP.get(program)
def _detect_pygments_content(content: str) -> str | None:
def _detect_pygments_content(
content: str,
debug: DebugLogger | None = None,
) -> str | None:
"""Return a lexer guessed from content when Pygments is confident."""
try:
lexer = guess_lexer(content)
except ClassNotFound:
log_debug(debug, "type: Pygments could not guess a lexer from content")
return None
aliases: list[str] = getattr(lexer, "aliases", [])
@@ -194,8 +200,29 @@ def _detect_pygments_content(content: str) -> str | None:
analyse_text = getattr(lexer, "analyse_text", None)
score_value = analyse_text(content) if callable(analyse_text) else 0.0
score = float(score_value) if isinstance(score_value, Real) else 0.0
if alias == "text" or score < 0.5:
guessed = alias if alias is not None else lexer.__class__.__name__
log_debug(debug, f"type: content guess -> lexer={guessed!r}, score={score:.3f}")
if alias is None:
log_debug(debug, "type: rejected content guess because the lexer has no alias")
return None
if alias == "text":
log_debug(
debug,
"type: rejected content guess because the lexer resolved to plain text",
)
return None
if score < 0.5:
log_debug(
debug,
"type: rejected content guess because the score is below 0.500",
)
return None
log_debug(debug, f"type: inferred {alias!r} from heuristic content guessing")
return alias
@@ -204,6 +231,7 @@ def detect_type(
content: str | None = None,
explicit_type: str | None = None,
guess_content: bool = False,
debug: DebugLogger | None = None,
) -> str:
"""Detect the file type for syntax highlighting.
@@ -221,25 +249,32 @@ def detect_type(
content: File content for JSON detection.
explicit_type: Override auto-detection with explicit type.
guess_content: Enable heuristic content-based lexer guessing.
debug: Optional debug logger for inference details.
Returns:
Pygments lexer name for the detected file type.
"""
if explicit_type is not None:
log_debug(debug, f"type: using explicit override {explicit_type!r}")
return explicit_type
if path is not None:
p = Path(path)
name = p.name
if name in _FILENAME_MAP:
return _FILENAME_MAP[name]
detected = _FILENAME_MAP[name]
log_debug(debug, f"type: inferred {detected!r} from filename {name!r}")
return detected
suffix = p.suffix.lower()
if suffix in EXTENSION_MAP:
return EXTENSION_MAP[suffix]
detected = EXTENSION_MAP[suffix]
log_debug(debug, f"type: inferred {detected!r} from extension {suffix!r}")
return detected
if content is not None:
shebang_type = _detect_shebang(content)
if shebang_type is not None:
log_debug(debug, f"type: inferred {shebang_type!r} from shebang")
return shebang_type
stripped = content.strip()
@@ -249,13 +284,17 @@ def detect_type(
):
try:
json.loads(stripped)
log_debug(debug, "type: inferred 'json' from JSON content")
return "json"
except (json.JSONDecodeError, ValueError):
pass
log_debug(debug, "type: JSON-like content failed to parse")
if guess_content:
pygments_type = _detect_pygments_content(content)
pygments_type = _detect_pygments_content(content, debug=debug)
if pygments_type is not None:
return pygments_type
else:
log_debug(debug, "type: skipped heuristic content guessing")
log_debug(debug, "type: fell back to 'text'")
return "text"

View File

@@ -9,8 +9,10 @@ import subprocess
from rich.pager import Pager, SystemPager
from rp.debug import DebugLogger, log_debug
def _mouse_capable_less() -> str | None:
def _mouse_capable_less(debug: DebugLogger | None = None) -> str | None:
"""Return a ``less`` path that likely supports ``--mouse``.
Mouse support was added in ``less`` 543. This probe is best-effort: it
@@ -24,6 +26,7 @@ def _mouse_capable_less() -> str | None:
"""
less = shutil.which("less")
if less is None:
log_debug(debug, "pager: 'less' was not found")
return None
try:
@@ -31,16 +34,21 @@ def _mouse_capable_less() -> str | None:
[less, "--version"], capture_output=True, text=True, timeout=5
)
except (subprocess.TimeoutExpired, OSError):
log_debug(debug, "pager: failed to probe the installed 'less' binary")
return None
version_str = result.stdout or result.stderr or ""
match = re.search(r"\bless\s+(\d+)\b", version_str, re.IGNORECASE)
if match is None:
log_debug(debug, "pager: could not parse the installed 'less' version")
return None
if int(match.group(1)) < 543:
version = int(match.group(1))
if version < 543:
log_debug(debug, f"pager: installed 'less' {version} is too old for --mouse")
return None
log_debug(debug, f"pager: using 'less' {version} from {less!r}")
return less
@@ -53,29 +61,41 @@ class MousePager(Pager):
trigger a second pager session.
"""
def __init__(self, debug: DebugLogger | None = None) -> None:
"""Initialize the pager with an optional debug logger."""
self._debug = debug
def show(self, content: str) -> None:
"""Display rendered content in ``less -R --mouse`` when possible.
Args:
content: Fully rendered text from Rich.
"""
less = _mouse_capable_less()
less = _mouse_capable_less(self._debug)
if less is None:
log_debug(self._debug, "pager: falling back to Rich's SystemPager")
SystemPager().show(content)
return
try:
log_debug(self._debug, "pager: launching 'less -R --mouse'")
result = subprocess.run(
[less, "-R", "--mouse"],
input=content,
text=True,
)
except OSError:
log_debug(self._debug, "pager: failed to launch 'less', using SystemPager")
SystemPager().show(content)
return
if result.returncode in (-signal.SIGINT, 128 + signal.SIGINT):
log_debug(self._debug, "pager: interrupted by user")
return
if result.returncode != 0:
log_debug(
self._debug,
f"pager: 'less' exited with status {result.returncode}, using SystemPager",
)
SystemPager().show(content)

View File

@@ -10,6 +10,7 @@ from rich.markdown import Markdown
from rich.padding import Padding
from rich.syntax import Syntax
from rp.debug import DebugLogger, log_debug
from rp.pager import MousePager
@@ -21,11 +22,13 @@ class RenderOptions:
theme: Pygments color theme name.
line_numbers: Show line numbers. ``None`` enables them for code only.
pager: Use pager for output. ``None`` auto-detects terminal output.
debug: Optional debug logger for render and pager decisions.
"""
theme: str = "monokai"
line_numbers: bool | None = None
pager: bool | None = None
debug: DebugLogger | None = None
_MARKDOWN_TYPES: set[str] = {"markdown", "md"}
@@ -49,12 +52,27 @@ def render(
line_numbers = options.line_numbers
if line_numbers is None:
line_numbers = file_type not in _MARKDOWN_TYPES and file_type not in _JSON_TYPES
log_debug(
options.debug,
f"render: auto-set line_numbers={line_numbers} for {file_type!r}",
)
use_pager = options.pager
if use_pager is None:
import sys
use_pager = sys.stdout.isatty()
stdout_is_tty = sys.stdout.isatty()
use_pager = stdout_is_tty
log_debug(
options.debug,
f"pager: auto-detected {'enabled' if use_pager else 'disabled'} "
f"because stdout is {'a' if stdout_is_tty else 'not a'} TTY",
)
else:
log_debug(
options.debug,
f"pager: explicitly {'enabled' if use_pager else 'disabled'}",
)
renderable: RenderableType
if file_type in _MARKDOWN_TYPES:
@@ -63,6 +81,7 @@ def render(
try:
renderable = RichJSON(content)
except (SyntaxError, ValueError):
log_debug(options.debug, "render: invalid JSON, falling back to syntax")
renderable = Syntax(
content, "json", theme=options.theme, line_numbers=line_numbers
)
@@ -72,6 +91,10 @@ def render(
content, file_type, theme=options.theme, line_numbers=line_numbers
)
except Exception:
log_debug(
options.debug,
f"render: unknown lexer {file_type!r}, falling back to plain text",
)
renderable = Syntax(
content, "text", theme=options.theme, line_numbers=line_numbers
)
@@ -79,7 +102,9 @@ def render(
padded = Padding(renderable, (1, 2))
if use_pager:
with console.pager(pager=MousePager(), styles=True):
log_debug(options.debug, "pager: opening pager")
with console.pager(pager=MousePager(debug=options.debug), styles=True):
console.print(padded)
else:
log_debug(options.debug, "pager: writing directly to the console")
console.print(padded)

View File

@@ -75,6 +75,7 @@ class TestFileInput:
content="x = 1\n",
explicit_type=None,
guess_content=False,
debug=None,
)
def test_render_called_with_correct_options(self, tmp_file) -> None:
@@ -182,8 +183,41 @@ class TestStdinInput:
content="hello\n",
explicit_type=None,
guess_content=False,
debug=None,
)
def test_debug_env_enables_debug_logger(self) -> None:
with patch("rp.cli.detect_type") as mock_detect_type:
mock_detect_type.return_value = "text"
with patch("rp.cli.render"):
runner.invoke(
app, ["--no-pager"], input="hello\n", env={"RP_DEBUG": "1"}
)
_, kwargs = mock_detect_type.call_args
assert kwargs["debug"] is not None
def test_debug_output_stays_on_stderr(self, tmp_file) -> None:
file = tmp_file("# Hello\n", suffix=".md")
result = runner.invoke(app, [str(file), "--no-pager"], env={"RP_DEBUG": "1"})
normalized_stderr = result.stderr.replace("\n", "")
assert result.exit_code == 0
assert "[rp debug]" not in result.stdout
assert "Hello" in result.stdout
assert "[rp debug] input: reading file" in result.stderr
assert repr(str(file)) in normalized_stderr
assert (
"[rp debug] type: inferred 'markdown' from extension '.md'" in result.stderr
)
assert (
"[rp debug] render: auto-set line_numbers=False for 'markdown'"
in result.stderr
)
assert "[rp debug] pager: explicitly disabled" in result.stderr
assert "[rp debug] pager: writing directly to the console" in result.stderr
def test_stdin_shows_tty_prompt(self) -> None:
"""When stdin is a TTY and no input is piped, show the reading hint."""
with patch("rp.cli.sys.stdin.isatty", return_value=True):

60
tests/test_debug.py Normal file
View File

@@ -0,0 +1,60 @@
"""Tests for debug helpers."""
from __future__ import annotations
import io
from rich.console import Console
from rp.debug import DEBUG_ENV_VAR, env_debug_enabled, log_debug, make_debug_logger
class TestEnvDebugEnabled:
"""Environment-based debug mode toggles."""
def test_disabled_by_default(self) -> None:
assert env_debug_enabled({}) is False
def test_false_like_values_disable_debug(self) -> None:
for value in ["", "0", "false", "no", "off"]:
assert env_debug_enabled({DEBUG_ENV_VAR: value}) is False
def test_false_like_values_are_trimmed_and_case_insensitive(self) -> None:
for value in [" False ", "\tNO\n", " Off "]:
assert env_debug_enabled({DEBUG_ENV_VAR: value}) is False
def test_truthy_values_enable_debug(self) -> None:
assert env_debug_enabled({DEBUG_ENV_VAR: "1"}) is True
assert env_debug_enabled({DEBUG_ENV_VAR: "true"}) is True
def test_truthy_values_are_trimmed_and_case_insensitive(self) -> None:
for value in [" TRUE ", " Yes ", "\ton\n"]:
assert env_debug_enabled({DEBUG_ENV_VAR: value}) is True
class TestMakeDebugLogger:
"""Console-backed debug logger output."""
def test_logs_visible_prefix(self) -> None:
stream = io.StringIO()
console = Console(file=stream, force_terminal=False)
logger = make_debug_logger(console, enabled=True)
assert logger is not None
logger("hello")
assert stream.getvalue() == "[rp debug] hello\n"
class TestLogDebug:
"""Nil-safe debug logger forwarding."""
def test_noop_when_logger_is_none(self) -> None:
log_debug(None, "hello")
def test_forwards_to_logger(self) -> None:
messages: list[str] = []
log_debug(messages.append, "hello")
assert messages == ["hello"]

View File

@@ -198,6 +198,30 @@ class TestGuessContent:
assert detect_type(content=sample_json, guess_content=True) == "json"
class TestDebugLogging:
"""Debug logging describes inference decisions."""
def test_logs_extension_source(self) -> None:
messages: list[str] = []
assert detect_type(path="script.py", debug=messages.append) == "python"
assert messages == ["type: inferred 'python' from extension '.py'"]
def test_logs_content_guess_and_score(self) -> None:
messages: list[str] = []
diff = "--- a/file\n+++ b/file\n@@ -1 +1 @@\n-old\n+new\n"
assert (
detect_type(content=diff, guess_content=True, debug=messages.append)
== "diff"
)
assert any(
"type: content guess -> lexer='diff', score=" in message
for message in messages
)
assert "type: inferred 'diff' from heuristic content guessing" in messages
class TestFallback:
"""Priority 7: fallback to 'text'."""

View File

@@ -25,6 +25,14 @@ class TestMouseCapableLess:
with patch("rp.pager.shutil.which", return_value=None):
assert _mouse_capable_less() is None
def test_logs_less_not_found(self) -> None:
messages: list[str] = []
with patch("rp.pager.shutil.which", return_value=None):
assert _mouse_capable_less(messages.append) is None
assert messages == ["pager: 'less' was not found"]
def test_returns_none_when_less_too_old(self) -> None:
with patch("rp.pager.shutil.which", return_value="/usr/bin/less"):
mock_result = MagicMock()
@@ -99,6 +107,19 @@ class TestMousePager:
mock_instance.show.assert_called_once_with("content")
def test_logs_system_pager_fallback(self) -> None:
messages: list[str] = []
pager = MousePager(debug=messages.append)
with patch("rp.pager._mouse_capable_less", return_value=None):
with patch("rp.pager.SystemPager") as mock_system_pager:
mock_instance = MagicMock()
mock_system_pager.return_value = mock_instance
pager.show("content")
assert messages == ["pager: falling back to Rich's SystemPager"]
def test_uses_less_when_available(self) -> None:
pager = MousePager()
mock_result = MagicMock()

View File

@@ -35,6 +35,10 @@ class TestRenderOptions:
assert opts.line_numbers is True
assert opts.pager is False
def test_default_debug_is_none(self) -> None:
opts = RenderOptions()
assert opts.debug is None
class TestRenderMarkdown:
"""Markdown rendering."""
@@ -238,6 +242,18 @@ class TestPagerBehavior:
assert len(capture_console.file.getvalue()) > 0
mock_pager.assert_not_called()
def test_logs_auto_pager_decision(
self, capture_console, sample_python: str
) -> None:
messages: list[str] = []
opts = RenderOptions(pager=None, debug=messages.append)
with patch("sys.stdout.isatty", return_value=False):
render(sample_python, "python", capture_console, opts)
assert "pager: auto-detected disabled because stdout is not a TTY" in messages
assert "pager: writing directly to the console" in messages
class TestPadding:
"""Rendered output is wrapped in padding."""