Skip to content

Commit 1ef06d8

Browse files
refactor: enhance Config and command base with comprehensive scenario-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>
1 parent edac329 commit 1ef06d8

File tree

3 files changed

+73
-24
lines changed

3 files changed

+73
-24
lines changed

src/molecule/command/base.py

Lines changed: 39 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,19 @@
5050
from molecule.types import CommandArgs, MoleculeArgs, ScenariosResults
5151

5252

53+
def _log(scenario_name: str, step: str, message: str, level: str = "info") -> None:
54+
"""Create scenario logger on-demand and log message.
55+
56+
Args:
57+
scenario_name: Name of the scenario for context.
58+
step: Step name for context (e.g., 'discovery', 'prerun', 'reset').
59+
message: Log message (pre-formatted, no placeholders).
60+
level: Log level ('info', 'warning', 'error', 'debug').
61+
"""
62+
scenario_log = logger.get_scenario_logger(__name__, scenario_name, step)
63+
getattr(scenario_log, level)(message)
64+
65+
5366
class Base(abc.ABC):
5467
"""An abstract base class used to define the command interface."""
5568

@@ -170,10 +183,11 @@ def _generate_scenarios(
170183
if scenario_names is not None:
171184
for scenario_name in scenario_names:
172185
if scenario_name != "*" and scenarios:
173-
scenario_log = logger.get_scenario_logger(__name__, scenario_name)
174-
scenario_log.info(
175-
"scenario test matrix: %s",
176-
", ".join(scenarios.sequence(scenario_name)),
186+
# Use generic "discovery" step since this is scenario discovery phase
187+
_log(
188+
scenario_name,
189+
"discovery",
190+
f"scenario test matrix: {', '.join(scenarios.sequence(scenario_name))}",
177191
)
178192

179193
return scenarios
@@ -202,16 +216,22 @@ def _run_scenarios(
202216
for scenario in scenarios.all:
203217
if scenario.config.config["prerun"]:
204218
role_name_check = scenario.config.config["role_name_check"]
205-
scenario_log = logger.get_scenario_logger(__name__, scenario.config.scenario.name)
206-
scenario_log.info("Performing prerun with role_name_check=%s...", role_name_check)
219+
_log(
220+
scenario.config.scenario.name,
221+
"prerun",
222+
f"Performing prerun with role_name_check={role_name_check}...",
223+
)
207224
scenario.config.runtime.prepare_environment(
208225
install_local=True,
209226
role_name_check=role_name_check,
210227
)
211228

212229
if command_args.get("subcommand") == "reset":
213-
scenario_log = logger.get_scenario_logger(__name__, scenario.config.scenario.name)
214-
scenario_log.info("Removing %s", scenario.ephemeral_directory)
230+
_log(
231+
scenario.config.scenario.name,
232+
"reset",
233+
f"Removing {scenario.ephemeral_directory}",
234+
)
215235
shutil.rmtree(scenario.ephemeral_directory)
216236
return
217237
try:
@@ -225,8 +245,13 @@ def _run_scenarios(
225245
f"An error occurred during the {scenario.config.subcommand} sequence action: "
226246
f"'{scenario.config.action}'. Cleaning up."
227247
)
228-
scenario_log = logger.get_scenario_logger(__name__, scenario.config.scenario.name)
229-
scenario_log.warning(msg)
248+
step_name = getattr(scenario.config, "action", "cleanup")
249+
_log(
250+
scenario.config.scenario.name,
251+
step_name,
252+
msg,
253+
level="warning",
254+
)
230255
execute_subcommand(scenario.config, "cleanup")
231256
destroy_results = execute_subcommand_default(default_config, "destroy")
232257
if destroy_results is not None:
@@ -272,11 +297,11 @@ def execute_subcommand_default(
272297
# clear results for later reuse
273298
default.results = []
274299
return results
275-
# Use the default scenario name for this warning since it's about the default scenario
276-
scenario_log = logger.get_scenario_logger(__name__, default.name)
277-
scenario_log.warning(
278-
"%s not found in default scenario, falling back to current scenario",
300+
_log(
301+
default.name,
279302
subcommand,
303+
f"{subcommand} not found in default scenario, falling back to current scenario",
304+
level="warning",
280305
)
281306
return None
282307

src/molecule/config.py

Lines changed: 18 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,6 @@
2222
from __future__ import annotations
2323

2424
import copy
25-
import logging
2625
import os
2726
import warnings
2827

@@ -32,7 +31,7 @@
3231

3332
from ansible_compat.ports import cache, cached_property
3433

35-
from molecule import api, interpolation, platforms, scenario, state, util
34+
from molecule import api, interpolation, logger, platforms, scenario, state, util
3635
from molecule.app import get_app
3736
from molecule.data import __file__ as data_module
3837
from molecule.dependency import ansible_galaxy, shell
@@ -55,7 +54,6 @@
5554
from molecule.verifier.base import Verifier
5655

5756

58-
LOG = logging.getLogger(__name__)
5957
MOLECULE_PARALLEL: bool = boolean(os.environ.get("MOLECULE_PARALLEL", ""))
6058
MOLECULE_DEBUG: bool = boolean(os.environ.get("MOLECULE_DEBUG", "False"))
6159
MOLECULE_VERBOSITY: int = int(os.environ.get("MOLECULE_VERBOSITY", "0"))
@@ -287,7 +285,7 @@ def collection(self) -> CollectionData | None:
287285

288286
important_keys = {"name", "namespace"}
289287
if missing_keys := important_keys.difference(galaxy_data.keys()):
290-
LOG.warning(
288+
self._log.warning(
291289
"The detected galaxy.yml file (%s) is invalid, missing mandatory field %s",
292290
galaxy_file,
293291
util.oxford_comma(missing_keys),
@@ -401,6 +399,15 @@ def scenario(self) -> scenario.Scenario:
401399
"""
402400
return scenario.Scenario(self)
403401

402+
@property
403+
def _log(self) -> logger.ScenarioLoggerAdapter:
404+
"""Get a scenario logger with config step context.
405+
406+
Returns:
407+
A scenario logger adapter with current scenario and step context.
408+
"""
409+
return logger.get_scenario_logger(__name__, self.scenario.name, "config")
410+
404411
@cached_property
405412
def state(self) -> State:
406413
"""Molecule state object.
@@ -416,7 +423,7 @@ def state(self) -> State:
416423
if my_state.molecule_yml_date_modified is None:
417424
my_state.change_state("molecule_yml_date_modified", modTime)
418425
elif my_state.molecule_yml_date_modified != modTime:
419-
LOG.warning(
426+
self._log.warning(
420427
"The scenario config file ('%s') has been modified since the scenario was created. "
421428
"If recent changes are important, reset the scenario with 'molecule destroy' to clean up created items or "
422429
"'molecule reset' to clear current configuration.",
@@ -478,7 +485,7 @@ def _get_driver_name(self) -> str:
478485
f"has changed and now defines '{driver_from_scenario}'. "
479486
"To change drivers, run 'molecule destroy' for converged scenarios or 'molecule reset' otherwise."
480487
)
481-
LOG.warning(msg)
488+
self._log.warning(msg)
482489

483490
return driver_name
484491

@@ -670,8 +677,12 @@ def _validate(self) -> None:
670677
Raises:
671678
MoleculeError: when config file fails to validate.
672679
"""
680+
# Use scenario logger with hardcoded values since scenario property isn't available yet
681+
scenario_name = self.config["scenario"]["name"]
682+
validation_log = logger.get_scenario_logger(__name__, scenario_name, "validate")
683+
673684
msg = f"Validating schema {self.molecule_file}."
674-
LOG.debug(msg)
685+
validation_log.debug(msg)
675686

676687
errors = schema_v3.validate(self.config)
677688
if errors:

tests/unit/test_config.py

Lines changed: 16 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
from __future__ import annotations
2121

2222
import copy
23+
import logging
2324
import os
2425

2526
from pathlib import Path
@@ -391,14 +392,26 @@ def test_get_defaults( # noqa: D103
391392
def test_validate( # noqa: D103
392393
mocker: MockerFixture,
393394
config_instance: config.Config,
394-
patched_logger_debug: Mock,
395+
caplog: pytest.LogCaptureFixture,
395396
) -> None:
396397
m = mocker.patch("molecule.model.schema_v3.validate")
397398
m.return_value = None
398399

399-
config_instance._validate()
400+
with caplog.at_level(logging.DEBUG):
401+
config_instance._validate()
402+
403+
# Check that debug message was logged
404+
assert len(caplog.records) == 1
405+
406+
# Check the log message content
407+
record = caplog.records[0]
408+
assert "Validating schema" in record.message
409+
assert config_instance.molecule_file in record.message
400410

401-
assert patched_logger_debug.call_count == 1
411+
# Check that scenario logger extras are present
412+
assert hasattr(record, "molecule_scenario")
413+
assert hasattr(record, "molecule_step")
414+
assert record.molecule_step == "validate"
402415

403416
m.assert_called_with(config_instance.config)
404417

0 commit comments

Comments
 (0)