Add structured logging for setup and teardown steps

This change improves test step logging by introducing structured,
visually distinct banners for setup and teardown stages. All three stages —
setup, execution, and teardown — now use consistent formatting and
independent step counters.

Each stage logs with a unique source prefix (TSU, TST, TTD) to enhance
readability and enable grep-friendly, machine-parsable log analysis.

Step counters are reset before each test via pytest_runtest_setup.
Teardown steps can be registered using request.addfinalizer() to ensure
post-test cleanup is consistently logged.

These enhancements improve clarity, support structured debugging, and
make it easier to differentiate test phases in log output.

Test Plan:
- Verified log output for setup, test, and teardown stages.
- Confirmed step counters reset between test cases.
- Manually validated formatting, alignment, and log source prefixes.

Change-Id: I363d6aa10a6d63697c68bd40dd8c08a23c7d96fd
Signed-off-by: Andrew Vaillancourt <andrew.vaillancourt@windriver.com>
This commit is contained in:
Andrew Vaillancourt
2025-06-12 15:33:44 -04:00
parent 332e7e0062
commit 4114b15a97
3 changed files with 121 additions and 11 deletions

View File

@ -25,7 +25,9 @@ class AutomationLogger(logging.getLoggerClass()):
super().__init__(name, level)
self.log_folder = None
self.test_case_log_dir = None
self._step_counter = 0 # for use in test case step
self._test_case_step_counter = 0
self._setup_step_counter = 0
self._teardown_step_counter = 0
def log(self, level: int, message: str, *args, **kwargs) -> None:
"""
@ -130,24 +132,78 @@ class AutomationLogger(logging.getLoggerClass()):
"""
return self.test_case_log_dir
def reset_step_counter(self) -> None:
"""Reset the test step counter at the beginning of each test case."""
self._step_counter = 0
def reset_all_step_counters(self) -> None:
"""Reset all internal step counters: setup, test case, and teardown."""
self._test_case_step_counter = 0
self._setup_step_counter = 0
self._teardown_step_counter = 0
def log_test_case_step(self, description: str, numbered: bool = True) -> None:
"""
Log a test step with optional automatic numbering and a distinct 'TST' source.
Log a test case step with optional automatic numbering and a distinct 'TST' source.
Args:
description (str): A short description of the test step.
numbered (bool): Whether to auto-increment and include the step number.
"""
if numbered:
self._step_counter += 1
message = f"Test Step {self._step_counter}: {description}"
self._test_case_step_counter += 1
step_num = self._test_case_step_counter if numbered else None
banner_line = self._format_step_tag("Test", step_num, description)
self._log(logging.INFO, banner_line, None, stacklevel=2, extra={"source": "TST"})
def log_setup_step(self, description: str, numbered: bool = True) -> None:
"""
Log a setup step with optional automatic numbering and a distinct 'TSU' source.
Args:
description (str): A short description of the setup step.
numbered (bool): Whether to auto-increment and include the step number.
"""
if numbered:
self._setup_step_counter += 1
step_num = self._setup_step_counter if numbered else None
banner_line = self._format_step_tag("Setup", step_num, description)
self._log(logging.INFO, banner_line, None, stacklevel=2, extra={"source": "TSU"})
def log_teardown_step(self, description: str, numbered: bool = True) -> None:
"""
Log a teardown step with optional automatic numbering and a distinct 'TTD' source.
Args:
description (str): A short description of the teardown step.
numbered (bool): Whether to auto-increment and include the step number.
"""
if numbered:
self._teardown_step_counter += 1
step_num = self._teardown_step_counter if numbered else None
banner_line = self._format_step_tag("Teardown", step_num, description)
self._log(logging.INFO, banner_line, None, stacklevel=2, extra={"source": "TTD"})
def _format_step_tag(self, tag: str, step_number: int | None, description: str = "") -> str:
"""
Format a standardized left-aligned single-line banner.
Args:
tag (str): The stage label (e.g., "SETUP", "TEST", "TEARDOWN").
step_number (int | None): Step number within the stage. Optional.
description (str): Step description.
Returns:
str: A left-aligned banner like:
-------------------- [ Test Step 2: Validate throughput ] ---------------------
"""
banner_char = "-"
total_width = 90
label = tag.title()
if step_number is not None:
content = f"[ {label} Step {step_number}: {description} ]"
else:
message = f"Test Step: {description}"
self._log(logging.INFO, message, None, stacklevel=2, extra={"source": "TST"})
content = f"[ {label}: {description} ]"
padding = total_width - len(content) - 1 # -1 for the leading space
return banner_char * 20 + " " + content + " " + banner_char * max(padding - 20, 0)
@staticmethod

View File

@ -62,3 +62,31 @@ def get_banner(banner_lines: List[str]) -> List[str]:
banner.append("***** " + line + " " * alignment_spaces_required + " *****")
banner.append("*" * (longest_line_length + 12))
return banner
def log_testcase_stage_banner(stage: str, test_name: str) -> None:
"""
Logs a standardized banner indicating the start of a test case stage, with a three-line format.
Args:
stage (str): One of 'Setup', 'Execution', or 'Teardown'.
test_name (str): The name of the test case.
"""
total_width = 90
banner_char = "=" # Change this to customize the banner character (e.g., '-', '#', '*')
banner_text = f"Starting {stage}: {test_name}"
inner_line = f" {banner_text} "
padding = max((total_width - len(inner_line)) // 2, 0)
middle_line = banner_char * padding + inner_line + banner_char * padding
if len(middle_line) < total_width:
middle_line += banner_char
border_line = banner_char * total_width
get_logger().log_info("") # clean line break
get_logger().log_info(border_line)
get_logger().log_info(middle_line)
get_logger().log_info(border_line)

View File

@ -66,11 +66,37 @@ def pytest_runtest_setup(item: Any):
item(Any): The test case item that we are about to execute.
"""
# Reset test step counter for this test case
get_logger().reset_step_counter()
# Reset all step counters for this test case
get_logger().reset_all_step_counters()
# add testcase log handler at test start
configure_testcase_log_handler(ConfigurationManager.get_logger_config(), item.name)
log_banners.log_test_start_banner(item)
log_banners.log_testcase_stage_banner("Setup", item.name)
def pytest_runtest_call(item: Any) -> None:
"""
Built-in pytest hook called to execute the test function.
This hook runs after setup and before teardown during the pytest lifecycle.
This implementation adds to the hook without modifying core test execution behavior.
It logs a visual banner to mark the beginning of the test's execution phase.
Args:
item (Any): The test case item being executed.
"""
log_banners.log_testcase_stage_banner("Execution", item.name)
def pytest_runtest_teardown(item: Any) -> None:
"""
This will run before the test case enters teardown.
Args:
item (Any): The test case item.
"""
log_banners.log_testcase_stage_banner("Teardown", item.name)
def pytest_runtest_makereport(item: Any, call: Any):