Skip to content

feat: enhance logging with consistent scenario and step information#4483

Merged
cidrblock merged 2 commits intoansible:mainfrom
cidrblock:feat/enhanced-log-adapter
Jul 28, 2025
Merged

feat: enhance logging with consistent scenario and step information#4483
cidrblock merged 2 commits intoansible:mainfrom
cidrblock:feat/enhanced-log-adapter

Conversation

@cidrblock
Copy link
Copy Markdown

Enhanced Logging with Consistent Scenario and Step Information

User-Facing Improvements

Enhanced Molecule's logging to provide consistent, structured messages that include scenario name and execution step information for better debugging and workflow visibility.

New Consistent Format:

INFO     default ➜ syntax: Starting
INFO     default ➜ syntax: Completed
INFO     test_scenario ➜ converge: Starting  
INFO     test_scenario ➜ converge: Completed

Visual styling: Green scenario + Yellow step + Bright cyan status + Unicode arrow

Benefits:

  • Clear visibility into which scenario and step is executing
  • Consistent message format across command executions
  • Complete lifecycle tracking (Starting/Completed) for better debugging
  • Enhanced visual clarity with Ansible-aligned color scheme

Technical Implementation

Implemented a dual-output approach to resolve test compatibility issues while maintaining rich visual formatting.

Core Changes:

  • Dual Methods: format_log_level() and format_scenario() return (colored_version, plain_version) tuples
  • Log Record Enhancement: Populate molecule_scenario and molecule_step extras, then update record msg with formatted plain text
  • Test Compatibility: pytest.caplog captures meaningful structured data via log record extras
  • Handler Updates: MoleculeConsoleHandler generates both visual output (stderr) and test-friendly records

Log Extras Approach:
Python logging's extra parameter allows attaching arbitrary data to log records. We enhanced ScenarioLoggerAdapter to inject scenario/step context, then modify the log record's msg field with formatted output, enabling both rich visual display and structured test assertions.

Current Scope & Future Work

This enhancement covers command execution lifecycle logging through section_logger. Not all log messages throughout Molecule include scenario/step information yet. Future work will extend this consistent formatting to additional logging points across the codebase.

Example Test Data

record.molecule_scenario == "default"
record.molecule_step == "syntax"  
record.msg == "INFO     [default > syntax] Starting"

- Add format_log_level() and format_scenario() methods returning (colored, plain) tuples
- Update MoleculeConsoleHandler to generate both visual and test-friendly output
- Modify log records with plain text for pytest caplog compatibility
- Enhance ScenarioLoggerAdapter to include step information in log record extras
- Add exec_phase color (bright cyan) for execution lifecycle indicators
- Implement complete lifecycle logging: Starting/Completed messages
- Update tests to use structured log record extras (molecule_scenario, molecule_step)
- Remove duplicate original format methods for cleaner API

Resolves test compatibility issues while maintaining beautiful visual output.
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

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

Pull Request Overview

This PR enhances Molecule's logging system to provide consistent, structured scenario and step information across command executions. The primary purpose is to improve debugging and workflow visibility through standardized log formatting.

Key changes include:

  • Implementation of a dual-output logging approach that provides both colored terminal output and plain text for test compatibility
  • Enhanced logger methods to return tuples of (colored_version, plain_version) for consistent formatting
  • Addition of molecule_scenario and molecule_step attributes to log records for structured access

Reviewed Changes

Copilot reviewed 6 out of 6 changed files in this pull request and generated 1 comment.

Show a summary per file
File Description
src/molecule/ansi_output.py Updated format methods to return tuples with colored and plain versions, added exec_phase markup
src/molecule/logger.py Enhanced logging handlers and adapters to support dual-output and scenario/step context
tests/unit/test_ansi_output.py Updated tests to verify dual-output functionality and new markup processing
tests/unit/test_logger.py Added tests for scenario logger with step information
tests/unit/command/test_syntax.py Updated to test structured log record attributes instead of text content
tests/unit/command/test_check.py Updated to test structured log record attributes instead of text content

- Maintain original behavior to avoid duplicate log messages
- caplog works correctly with direct logger targeting and record.msg updates
- Addresses Copilot review feedback on PR ansible#4483
Copy link
Copy Markdown
Contributor

@alisonlhart alisonlhart left a comment

Choose a reason for hiding this comment

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

Awesome!

@cidrblock cidrblock merged commit 8433127 into ansible:main Jul 28, 2025
21 checks passed
cidrblock added a commit that referenced this pull request Jul 28, 2025
Problem: Several core components (dependency, provisioner, verifier, and
commands) cache their loggers at initialization, preventing them from
picking up dynamic scenario and step context during execution.

Solution: Converted self._log from instance variable to @Property in
multiple classes:
- Dependency (base, shell, ansible-galaxy)
- Provisioner (ansible, playbook, playbooks)
- Verifier (ansible, testinfra)
- Commands (create, destroy)

Each property now dynamically retrieves fresh scenario and step context
on access using getattr(self._config, 'action', default_step).

Impact: Log messages from these components now consistently show the
current scenario and step context in the format 'scenario ➜ step:
message'.

Testing: Verified via integration tests across multiple scenarios and
commands. The changes maintain compatibility with the dual-output
logging system introduced in PR #4483.
cidrblock added a commit that referenced this pull request Jul 28, 2025
…-aware logging (#4488)

## Summary

Comprehensive enhancement of Config class and command base logging with
scenario-aware context, building on the foundation from merged PRs #4483
and #4484.

## User-Facing Changes

**Enhanced logging context across all Config and command operations:**

### Before: Generic logging without context
```
DEBUG    Validating schema molecule.yml
WARNING  Driver 'default' is currently in use but config defines 'podman'
INFO     Performing prerun with role_name_check=0...
```

### After: Complete scenario and step context
```
DEBUG    smoke ➜ validate: Validating schema /path/to/molecule.yml
WARNING  smoke ➜ config: Driver 'default' is currently in use but config defines 'podman'  
INFO     smoke ➜ prerun: Performing prerun with role_name_check=0...
INFO     smoke ➜ discovery: scenario test matrix: syntax
```

## Technical Implementation

**🏗️ Config Class Enhancements:**
- Add reusable `@property _log` method to Config class for dynamic
scenario context
- Convert all Config logging calls to use scenario-aware loggers
- Enhanced validation logging with hardcoded scenario context during
bootstrap
- Improved galaxy file and driver validation warnings with full context

**🧹 Command Base Logger Consolidation:**
- Replace 5 scattered `get_scenario_logger()` calls with single global
`_log()` function
- Unified logging pattern: `_log(scenario_name, step, message,
level='info')`
- Pre-formatted messages eliminate complex placeholder handling
- Cleaner, more maintainable logger creation across all command
operations

**✅ Enhanced Test Coverage:**
- Updated `test_validate` to use `caplog` instead of mock patching
- Validates scenario logger extras: `molecule_scenario` and
`molecule_step`
- Robust verification of message content and context attributes

## Changes Included

**Config Class (4 commits):**
1. `feat: add step context to command base logger calls`
2. `feat: add scenario context to config file modification warning`  
3. `refactor: add reusable _log property to Config class`
4. `refactor: convert all Config logging to scenario-aware logging`

**Command Base Improvements (2 commits):**
5. `refactor: replace scattered logger initializations with global _log
function`
6. `fix: update test_validate to use caplog and check scenario logger
extras`

**Dependencies (Included):**
- Builds on: All cleanup commits from PR #4487 (unused logger removal)

## Dependencies

- **Depends on**: PR #4487 (unused logger cleanup)
- **Builds on**: PR #4484 (merged - dynamic properties for
dependency/provisioner/verifier)
- **Foundation**: PR #4483 (merged - enhanced logging adapter with
dual-output)

## Testing

- ✅ **Comprehensive**: All config tests passing (45/45)
- ✅ **Enhanced coverage**: Validates scenario logger extras in test
suite
- ✅ **Functional verification**: `molecule syntax` confirms enhanced
logging works
- ✅ **Backwards compatible**: No breaking changes to existing
functionality

## Impact

- **Complete Config context**: All Config operations now include
scenario and step information
- **Unified command logging**: Consistent pattern across all command
base operations
- **Better maintainability**: Single global `_log` function replaces
scattered initializations
- **Enhanced debugging**: Full context for configuration validation and
driver operations

---------

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

Archived in project

Development

Successfully merging this pull request may close these issues.

3 participants