vdk-structlog: filter vdk_step_name and vdk_step_type correctly

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

@@ -157,4 +157,5 @@ def create_formatter(logging_format: str, metadata_keys: str) -> [Formatter, Fil
             fmt=StructlogMetadataBuilder(metadata_keys).build_console_format()
         )
         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

@@ -162,16 +162,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"',
     },
 }
 
@@ -120,6 +126,46 @@ def test_stock_fields_removal(log_format):
                 assert re.search(stock_field_reps[shown_field], test_log) is not None
 
 
+@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 _run_job_and_get_logs():
     """
     Runs the necessary job and returns the output logs.