Skip to content

Route diagnostic output through Python logging#28

Open
delano wants to merge 1 commit intomainfrom
fix/output-buffering
Open

Route diagnostic output through Python logging#28
delano wants to merge 1 commit intomainfrom
fix/output-buffering

Conversation

@delano
Copy link
Member

@delano delano commented Mar 4, 2026

Summary

Replaces bare print() calls throughout the CLI with Python's logging module, giving us proper log levels, consistent formatting, and a clean mechanism for --quiet mode.

  • Every command module now uses logger = logging.getLogger(__name__) instead of print()
  • A custom _CLIFormatter in cli.py renders INFO as plain text (preserving existing CLI appearance) while WARNING+ gets a LEVEL module: prefix
  • New apply_quiet() helper sets root logger to WARNING, replacing scattered if not quiet: print() guards
  • New flush_output() helper ensures buffered log output is flushed before PTY/subprocess handoff (fixes potential output swallowing)
  • Intentional print() calls retained for machine-readable output (JSON), raw content display, interactive prompts, and table formatting

Tests updated across all command modules — instance tests use a _LiveStderrHandler fixture (capsys on stderr), other tests use caplog.

Review notes

  • Default log level changes from WARNING to INFO so CLI status messages appear by default (matching previous print() behavior)
  • A few f-strings slipped into logger calls in service/app.py and init.py — not blocking but inconsistent with %-style used elsewhere
  • One test assertion for dry-run output in test_config_transform.py was removed without migration to caplog

Test plan

  • All 1744 tests pass (3 skipped)
  • Verify --quiet suppresses INFO output on a live system
  • Verify --verbose enables DEBUG output
  • Check output appearance matches pre-migration behavior for common commands

Bare print() to stdout for status/error/warning messages caused output
buffering issues (e.g. shell command not displayed before PTY handoff)
and violated the Unix convention of diagnostics on stderr.

- Change default log level from WARNING to INFO so status messages
  remain visible; --verbose enables DEBUG; per-command --quiet raises
  to WARNING
- Add CLIFormatter that omits level/module prefix for INFO messages,
  preserving the existing UX for status output
- Add flush_output() utility called before subprocess/PTY handoff
- Add apply_quiet() utility for commands with --quiet flag
- Convert ~500 print() calls to logger.info/warning/error across 18
  source files; ~265 print() calls remain for program output (tables,
  JSON, diffs, passthrough)
- Update 96 test assertions from capsys to caplog
@claude
Copy link

claude bot commented Mar 4, 2026

Claude finished @delano's task —— View job


PR Review: Route diagnostic output through Python logging

Review Summary ✅

This is a well-executed logging migration that addresses real output buffering issues while maintaining clean CLI UX. The PR successfully converts ~500 print() calls across 37 files with proper test updates.

Code Quality Assessment

Excellent Implementation:

  • Clean architecture: Custom _CLIFormatter preserves CLI appearance for INFO messages while adding prefixes for WARNING+
  • Smart helper functions: apply_quiet() and flush_output() solve real PTY/subprocess handoff issues
  • Proper logger hierarchy: Consistent logger = logging.getLogger(__name__) pattern throughout
  • Test migration: Comprehensive updates from capsys to caplog, including custom _LiveStderrHandler fixture for instance tests

Minor Issues Found:

  1. Inconsistent string formatting in src/rots/commands/service/app.py:238-241 and src/rots/commands/init.py:79+:

    # Current f-string usage in logger calls
    logger.info(f"Initializing {pkg.name} instance '{instance}'")

    Should use %-style formatting for consistency with rest of codebase:

    logger.info("Initializing %s instance '%s'", pkg.name, instance)
  2. Missing test assertion: One test assertion for dry-run output in test_config_transform.py was removed without caplog migration (mentioned in PR notes)

Security & Performance ✅

  • Security: No concerns - logging doesn't expose sensitive data
  • Performance: Minimal overhead from logging framework, proper third-party logger suppression

Test Coverage ✅

  • All 1744 tests pass (3 skipped)
  • 42 test files updated with proper caplog/capsys usage
  • Custom test fixtures handle pytest stderr capture correctly

Recommendations

  1. Fix string formatting inconsistencies for maintainability
  2. Add the missing test assertion with caplog equivalent
  3. Consider adding a linting rule to prevent future f-string usage in logger calls

Overall Assessment: APPROVE

This PR significantly improves the codebase's diagnostic output handling while maintaining backward compatibility. The few minor issues are non-blocking and easily addressed in follow-up commits.

@gemini-code-assist
Copy link

Summary of Changes

Hello, I'm Gemini Code Assist1! I'm currently reviewing this pull request and will post my feedback shortly. In the meantime, here's a summary to help you and other reviewers quickly get up to speed!

This pull request significantly refactors the command-line interface's output mechanism by migrating from direct print() statements to Python's logging module. This change standardizes how diagnostic and informational messages are presented, offering granular control over verbosity and formatting. It introduces a custom formatter to maintain a clean user experience for informational messages while enhancing visibility for warnings and errors. Additionally, it provides robust solutions for managing quiet mode and ensuring output integrity during subprocess interactions, ultimately improving the maintainability and flexibility of the CLI's feedback system.

Highlights

  • Logging Integration: Replaced most bare print() calls across the CLI with Python's logging module, enabling structured logging with proper log levels and consistent formatting.
  • Custom CLI Formatter: Introduced a custom _CLIFormatter in cli.py to ensure INFO level messages appear as plain text (mimicking previous print() behavior), while WARNING and higher levels include a LEVEL module: prefix for clarity.
  • Quiet Mode Implementation: Implemented a new apply_quiet() helper function that sets the root logger to WARNING level when the --quiet flag is active, effectively suppressing INFO messages without needing scattered if not quiet: print() checks.
  • Output Flushing Mechanism: Added a flush_output() helper to ensure buffered log output is flushed to stdout and stderr before handing off to PTY or subprocesses, preventing potential output swallowing issues.
  • Test Suite Updates: Updated the test suite to use caplog for capturing log output, with a new _LiveStderrHandler fixture for instance tests to correctly capture stderr output from the logging system.
Changelog
  • src/rots/assets.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() statements with logger.info() and logger.warning() for manifest-related output.
  • src/rots/cli.py
    • Defined _CLIFormatter to customize log message formatting, suppressing prefixes for INFO level.
    • Modified _configure_logging to use _CLIFormatter and set the default logging level to INFO.
  • src/rots/commands/cloudinit/app.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.info() for creation and validation messages.
  • src/rots/commands/db.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.error() for error messages and logger.info() for backup/restore status.
  • src/rots/commands/dns/app.py
    • Replaced numerous print() calls with logger.error() and logger.info() for DNS command output.
  • src/rots/commands/env/app.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.error(), logger.info(), and logger.warning() for environment file processing messages.
  • src/rots/commands/host/_rsync.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() warning messages with logger.warning().
  • src/rots/commands/host/app.py
    • Imported logging and apply_quiet.
    • Initialized a module-level logger.
    • Integrated apply_quiet() into push, diff, and pull commands.
    • Replaced print() calls with logger.error() and logger.info() for host command output.
  • src/rots/commands/image/app.py
    • Imported apply_quiet.
    • Integrated apply_quiet() into pull, list_remote, build, and push commands.
    • Replaced print() calls with logger.error(), logger.info(), and logger.warning() for image management output.
  • src/rots/commands/init.py
    • Imported logging and apply_quiet.
    • Initialized a module-level logger.
    • Integrated apply_quiet() into the init command, conditionally based on check mode.
    • Replaced print() calls with logger.error(), logger.info(), and logger.warning() for initialization messages.
  • src/rots/commands/instance/_helpers.py
    • Imported the logging module.
    • Added flush_output() function to ensure buffered output is written.
    • Added apply_quiet() function to adjust logging level based on quiet flag.
    • Replaced print() calls with logger.warning() and logger.error() for deploy lock and instance processing.
  • src/rots/commands/instance/app.py
    • Imported apply_quiet and flush_output.
    • Integrated apply_quiet() into run, deploy, redeploy, and shell commands.
    • Added flush_output() before interactive and streaming subprocess calls.
    • Replaced print() calls with logger.info() and logger.error() for instance management output, retaining print() for JSON and raw content.
  • src/rots/commands/proxy/_helpers.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.info() for file transfer messages.
  • src/rots/commands/proxy/app.py
    • Renamed log variable to logger for consistency.
    • Replaced print() calls with logger.info() and logger.error() for proxy command output.
    • Updated log.isEnabledFor to logger.isEnabledFor.
  • src/rots/commands/service/_helpers.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() warning messages with logger.warning().
  • src/rots/commands/service/app.py
    • Replaced print() calls with logger.info(), logger.warning(), and logger.error() for service management output.
  • src/rots/config.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.info() for SSH connection status.
  • src/rots/quadlet.py
    • Imported the logging module.
    • Initialized a module-level logger.
    • Replaced print() calls with logger.error() and logger.warning() for quadlet generation warnings and errors.
  • tests/commands/cloudinit/test_app.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/host/test_app.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/host/test_rsync.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/image/test_app.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/image/test_build.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/image/test_image_ref_parsing.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/instance/conftest.py
    • Added _LiveStderrHandler class to correctly capture logging output to sys.stderr in tests.
    • Added _reset_logging_handlers fixture to ensure caplog works with the new logging setup.
  • tests/commands/instance/test_app.py
    • Adjusted assertions to check captured.err or combined output, reflecting logging to stderr.
  • tests/commands/instance/test_config_transform.py
    • Removed an assertion related to dry-run output, as noted in the PR description.
    • Adjusted assertions to check captured.err output.
  • tests/commands/instance/test_helpers.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/instance/test_shell.py
    • Adjusted assertions to check captured.err output.
  • tests/commands/proxy/test_app.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/service/test_app.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/test_db_commands.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/test_env.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/commands/test_init.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/test_cli.py
    • Updated test_verbose_false_passes_info_level_to_basicconfig to assert logging.INFO instead of logging.WARNING.
  • tests/test_image_build.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
  • tests/test_quadlet.py
    • Imported logging.
    • Updated tests to use caplog fixture for capturing log output instead of capsys.
Activity
  • The author, delano, created this pull request to refactor CLI output to use Python's logging module.
  • The description details the motivation, implementation specifics like _CLIFormatter, apply_quiet(), and flush_output(), and outlines intentional exceptions for print() usage.
  • Review notes highlight a change in default log level, minor f-string inconsistencies, and a removed test assertion.
Using Gemini Code Assist

The full guide for Gemini Code Assist can be found on our documentation page, here are some quick tips.

Invoking Gemini

You can request assistance from Gemini at any point by creating a comment using either /gemini <command> or @gemini-code-assist <command>. Below is a summary of the supported commands on the current page.

Feature Command Description
Code Review /gemini review Performs a code review for the current pull request in its current state.
Pull Request Summary /gemini summary Provides a summary of the current pull request in its current state.
Comment @gemini-code-assist Responds in comments when explicitly tagged, both in pull request comments and review comments.
Help /gemini help Displays a list of available commands.

Customization

To customize Gemini Code Assist for GitHub experience, repository maintainers can create a configuration file and/or provide a custom code review style guide (such as PEP-8 for Python) by creating and adding files to a .gemini/ folder in the base of the repository. Detailed instructions can be found here.

Limitations & Feedback

Gemini Code Assist may make mistakes. Please leave feedback on any instances where its feedback is incorrect or counter productive. You can react with 👍 and 👎 on @gemini-code-assist comments. If you're interested in giving your feedback about your experience with Gemini Code Assist for Github and other Google products, sign up here.

You can also get AI-powered code generation, chat, as well as code reviews directly in the IDE at no cost with the Gemini Code Assist IDE Extension.

Footnotes

  1. Review the Privacy Notices, Generative AI Prohibited Use Policy, Terms of Service, and learn how to configure Gemini Code Assist in GitHub here. Gemini can make mistakes, so double check it and use code with caution.

Copy link

@gemini-code-assist gemini-code-assist bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request is a great improvement, refactoring the CLI's output to use Python's logging module. This provides better structure, log levels, and a cleaner way to handle --quiet mode. The custom _CLIFormatter is a clever solution to maintain the existing look and feel for INFO-level messages.

I've made a few suggestions to improve consistency in logging practices and restore a test assertion that was removed. Specifically, I've pointed out a few places where f-strings are used in logger calls, which is inconsistent with the otherwise excellent use of %-style formatting. I also noticed a test assertion was removed and have suggested how to restore it using caplog.

Note: Security Review did not run due to the size of the PR.

print(f" Size: {size:,} bytes")
logger.info("Backup created: %s", target)
logger.info(" Source: %s", db_path)
logger.info(" Size: %s bytes", f"{size:,}")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

While this works, using an f-string for logging arguments is inconsistent with the %-style formatting used elsewhere in the codebase. This can lead to evaluating the expression even if the log level is not high enough to display the message. It would be more consistent to format the value before the logging call.

For example:

size_str = f"{size:,}"
logger.info("  Size:    %s bytes", size_str)

if _path_exists(path, executor):
if not quiet:
print(f" [ok] {path}")
logger.info(f" [ok] {path}")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

This log message uses an f-string. For consistency with the rest of the codebase and to leverage deferred formatting, please use %-style formatting.

Suggested change
logger.info(f" [ok] {path}")
logger.info(" [ok] %s", path)

Comment on lines +238 to +241
logger.info(f"Initializing {pkg.name} instance '{instance}'")
logger.info(f" Template: {pkg.template_unit}")
logger.info(f" Port: {port_num}")
logger.info(f" Bind: {bind}")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

These log messages use f-strings. For consistency and to take advantage of deferred formatting, it's better to use %-style formatting.

Suggested change
logger.info(f"Initializing {pkg.name} instance '{instance}'")
logger.info(f" Template: {pkg.template_unit}")
logger.info(f" Port: {port_num}")
logger.info(f" Bind: {bind}")
logger.info("Initializing %s instance '%s'", pkg.name, instance)
logger.info(" Template: %s", pkg.template_unit)
logger.info(" Port: %d", port_num)
logger.info(" Bind: %s", bind)

raise SystemExit(rc)
except KeyboardInterrupt:
print("\nStopped")
logger.info("\nStopped")

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Including a leading newline \n in a log message is unconventional and can lead to inconsistent log formatting. It's better to log the message directly and let the logging handler manage newlines.

Suggested change
logger.info("\nStopped")
logger.info("Stopped")

assert "new_value" in captured.out
# Should indicate dry-run
assert "dry run" in captured.out.lower() or "no changes made" in captured.out.lower()

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

This test assertion for the dry-run message was removed. Since the output is now logged, you can restore this check using the caplog fixture to ensure the dry-run message is correctly logged.

import logging

# Inside the test function
with caplog.at_level(logging.INFO):
    instance.config_transform(command="transform", dry_run=True)

captured = capsys.readouterr()
assert "old_value" in captured.out
assert "new_value" in captured.out
assert "dry run" in caplog.text.lower() or "no changes made" in caplog.text.lower()

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