From 4114b15a970b9f1281f331f95227fc8d9515f2b6 Mon Sep 17 00:00:00 2001 From: Andrew Vaillancourt Date: Thu, 12 Jun 2025 15:33:44 -0400 Subject: [PATCH] Add structured logging for setup and teardown steps MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- framework/logging/automation_logger.py | 74 ++++++++++++++++++++++---- framework/logging/log_banners.py | 28 ++++++++++ testcases/conftest.py | 30 ++++++++++- 3 files changed, 121 insertions(+), 11 deletions(-) diff --git a/framework/logging/automation_logger.py b/framework/logging/automation_logger.py index ae334a9d..2bc11899 100644 --- a/framework/logging/automation_logger.py +++ b/framework/logging/automation_logger.py @@ -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 diff --git a/framework/logging/log_banners.py b/framework/logging/log_banners.py index b9bbc2d6..a7373151 100644 --- a/framework/logging/log_banners.py +++ b/framework/logging/log_banners.py @@ -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) diff --git a/testcases/conftest.py b/testcases/conftest.py index 332be47c..1988d24c 100644 --- a/testcases/conftest.py +++ b/testcases/conftest.py @@ -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):