vdk-structlog: filter vdk_step_name and vdk_step_type correctly (#2968)

## Why?

vdk_step_name and vdk_step_type were not filtered correctly when using
json format

## What?

Make sure the metadata filter alwats executes last, even when
vdk_step_name and vdk_step_type are involved

Add separate functional test for vdk_step_name and vdk_step_type to
avoid conflict with file_name in other tests

## How was this tested?

Functional tests

## What kind of change is this?

Feature/non-breaking

---------

Signed-off-by: Dilyan Marinov <[email protected]>

projects/vdk-plugins/vdk-structlog/src/vdk/plugin/structlog/formatters.py

@@ -162,5 +162,5 @@ def create_formatter(
         )
         formatter = ConsoleFormatter(fmt=format_string)
         custom_key_filter = ConsoleMetadataFilter(key_set)
-
+    custom_key_filter.name = "metadata_filter"
     return formatter, custom_key_filter

projects/vdk-plugins/vdk-structlog/src/vdk/plugin/structlog/structlog_plugin.py

@@ -184,16 +184,25 @@ def run_job(self, context: JobContext) -> Optional[ExecutionResult]:
     @hookimpl(hookwrapper=True)
     def run_step(self, context: JobContext, step: Step) -> Optional[StepResult]:
         root_logger = logging.getLogger()
+        handler = root_logger.handlers[0]
+
+        # make sure the metadata filter executes last
+        # so that step_name and step_type are filtered if necessary
+        metadata_filter = [f for f in handler.filters if f.name == "metadata_filter"][0]
+        handler.removeFilter(metadata_filter)
+
         step_name_adder = AttributeAdder("vdk_step_name", step.name)
         step_type_adder = AttributeAdder("vdk_step_type", step.type)
-        for handler in root_logger.handlers:
-            handler.addFilter(step_name_adder)
-            handler.addFilter(step_type_adder)
+        handler.addFilter(step_name_adder)
+        handler.addFilter(step_type_adder)
+
+        # make sure the metadata filter executes last
+        # so that step_name and step_type are filtered if necessary
+        handler.addFilter(metadata_filter)
         out: HookCallResult
         out = yield
-        for handler in root_logger.handlers:
-            handler.removeFilter(step_name_adder)
-            handler.removeFilter(step_type_adder)
+        handler.removeFilter(step_name_adder)
+        handler.removeFilter(step_type_adder)
 
 
 @hookimpl

projects/vdk-plugins/vdk-structlog/tests/test_structlog.py

@@ -36,6 +36,8 @@
         "line_number": r"\s:[0-9]+",
         "function_name": "run",
         "vdk_job_name": JOB_NAME,
+        "vdk_step_name": r"10_dummy\.py",
+        "vdk_step_type": r"python",
     },
     "ltsv": {
         "timestamp": r"timestamp:\d+\.\d+",
@@ -44,6 +46,8 @@
         "line_number": "line_number:[0-9]+",
         "function_name": "function_name:run",
         "vdk_job_name": f"vdk_job_name:{JOB_NAME}",
+        "vdk_step_name": r"vdk_step_name:10_dummy\.py",
+        "vdk_step_type": "vdk_step_type:python",
     },
     "json": {
         "timestamp": r'"timestamp": \d+\.\d+',
@@ -52,6 +56,8 @@
         "line_number": '"lineno": [0-9]+',
         "function_name": '"funcName": "run"',
         "vdk_job_name": f'"vdk_job_name": "{JOB_NAME}"',
+        "vdk_step_name": '"vdk_step_name": "10_dummy.py"',
+        "vdk_step_type": '"vdk_step_type": "python"',
     },
 }
 
@@ -165,6 +171,46 @@ def test_custom_format_not_applied_for_non_console_formats(log_format):
             pytest.fail("Log statement with no bound context not found in logs")
 
 
+@pytest.mark.parametrize("log_format", ["console", "json", "ltsv"])
+def test_step_name_step_type(log_format):
+    stock_field_reps = STOCK_FIELD_REPRESENTATIONS[log_format]
+    with mock.patch.dict(
+        os.environ,
+        {
+            "VDK_LOGGING_METADATA": "vdk_step_type,vdk_step_name",
+            "VDK_LOGGING_FORMAT": log_format,
+        },
+    ):
+        logs = _run_job_and_get_logs()
+        test_log = _get_log_containing_s(logs, "Log statement with no bound context")
+        assert re.search(stock_field_reps["vdk_step_name"], test_log) is not None
+        assert re.search(stock_field_reps["vdk_step_type"], test_log) is not None
+
+    with mock.patch.dict(
+        os.environ,
+        {
+            "VDK_LOGGING_METADATA": "vdk_step_name",
+            "VDK_LOGGING_FORMAT": log_format,
+        },
+    ):
+        logs = _run_job_and_get_logs()
+        test_log = _get_log_containing_s(logs, "Log statement with no bound context")
+        assert re.search(stock_field_reps["vdk_step_name"], test_log) is not None
+        assert re.search(stock_field_reps["vdk_step_type"], test_log) is None
+
+    with mock.patch.dict(
+        os.environ,
+        {
+            "VDK_LOGGING_METADATA": "vdk_step_type",
+            "VDK_LOGGING_FORMAT": log_format,
+        },
+    ):
+        logs = _run_job_and_get_logs()
+        test_log = _get_log_containing_s(logs, "Log statement with no bound context")
+        assert re.search(stock_field_reps["vdk_step_name"], test_log) is None
+        assert re.search(stock_field_reps["vdk_step_type"], test_log) is not None
+
+
 def _matches_custom_format(log):
     pattern = re.compile(
         r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} \S{1,12} \S{1,8} .+"