vdk-structlog: support parse log level module and logger config granularity

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

@@ -0,0 +1,58 @@
+# Copyright 2021-2023 VMware, Inc.
+# SPDX-License-Identifier: Apache-2.0
+import logging
+import re
+
+from vdk.internal.core import errors
+
+
+def parse_log_level_module(log_level_module):
+    valid_logging_levels = [
+        "NOTSET",
+        "DEBUG",
+        "INFO",
+        "WARN",
+        "WARNING",
+        "ERROR",
+        "FATAL",
+        "CRITICAL",
+    ]
+    try:
+        if log_level_module and log_level_module.strip():
+            modules = log_level_module.split(";")
+            result = {}
+            for module in modules:
+                if module:
+                    module_and_level = module.split("=")
+                    if not re.search("[a-zA-Z0-9_.-]+", module_and_level[0].lower()):
+                        raise ValueError(
+                            f"Invalid logging module name: '{module_and_level[0]}'. "
+                            f"Must be alphanumerical/underscore characters."
+                        )
+                    if module_and_level[1].upper() not in valid_logging_levels:
+                        raise ValueError(
+                            f"Invalid logging level: '{module_and_level[1]}'. Must be one of {valid_logging_levels}."
+                        )
+                    result[module_and_level[0]] = {"level": module_and_level[1].upper()}
+            return result
+        else:
+            return {}
+    except Exception as e:
+        errors.report_and_throw(
+            errors.VdkConfigurationError(
+                "Invalid logging configuration passed to LOG_LEVEL_MODULE.",
+                f"Error is: {e}. log_level_module was set to {log_level_module}.",
+                "Set correctly configuration to log_level_debug configuration in format 'module=level;module2=level2'",
+            )
+        )
+
+
+def set_non_root_log_levels(vdk_log_level: str, log_level_module: str):
+    logging.getLogger("requests_kerberos").setLevel(logging.INFO)
+    logging.getLogger("requests_oauthlib").setLevel(logging.INFO)
+    logging.getLogger("urllib3").setLevel(logging.INFO)
+    logging.getLogger("vdk").setLevel(vdk_log_level)
+
+    parsed_log_levels = parse_log_level_module(log_level_module)
+    for logger_name, level_info in parsed_log_levels.items():
+        logging.getLogger(logger_name).setLevel(level_info["level"])

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

@@ -1,14 +1,15 @@
 # Copyright 2021-2023 VMware, Inc.
 # SPDX-License-Identifier: Apache-2.0
 import logging
+import os
 import sys
 from typing import List
 from typing import Optional
 
-from pythonjsonlogger import jsonlogger
 from vdk.api.plugin.hook_markers import hookimpl
 from vdk.api.plugin.plugin_registry import HookCallResult
 from vdk.api.plugin.plugin_registry import IPluginRegistry
+from vdk.internal.builtin_plugins.config import vdk_config
 from vdk.internal.builtin_plugins.run.execution_results import ExecutionResult
 from vdk.internal.builtin_plugins.run.execution_results import StepResult
 from vdk.internal.builtin_plugins.run.job_context import JobContext
@@ -24,6 +25,7 @@
 from vdk.plugin.structlog.constants import STRUCTLOG_LOGGING_METADATA_KEY
 from vdk.plugin.structlog.filters import AttributeAdder
 from vdk.plugin.structlog.formatters import create_formatter
+from vdk.plugin.structlog.log_level_utils import set_non_root_log_levels
 
 """
 Handlers
@@ -49,7 +51,7 @@
 
 class BoundLogger(logging.LoggerAdapter):
     def process(self, msg, kwargs):
-        # merge bound extra dict with existing exra dict if any
+        # merge bound extra dict with existing extra dict if any
         if "extra" in kwargs:
             kwargs["extra"] = {**self.extra, **kwargs["extra"]}
         else:
@@ -75,8 +77,10 @@ def vdk_configure(self, config_builder: ConfigurationBuilder):
             ),
             description=(
                 f"Possible values: {STRUCTLOG_LOGGING_METADATA_ALL_KEYS}"
-                "User-defined key-value pairs added to the logger's context will be displayed after the metadata, but before the message"
-                "Keys for user-defined key-value pairs have to be added in this config option for the values to be displayed in the metadata"
+                "User-defined key-value pairs added to the logger's context will be displayed after the metadata, "
+                "but before the message"
+                "Keys for user-defined key-value pairs have to be added in this config option for the values to be "
+                "displayed in the metadata"
             ),
         )
 
@@ -96,6 +100,18 @@ def vdk_configure(self, config_builder: ConfigurationBuilder):
 
     @hookimpl
     def vdk_initialize(self, context: CoreContext):
+        if logging.getLogger().getEffectiveLevel() == logging.NOTSET:
+            log_level = os.environ.get(
+                "LOG_LEVEL_VDK", os.environ.get("VDK_LOG_LEVEL_VDK", "INFO")
+            ).upper()
+            logging.getLogger().setLevel(log_level)
+        vdk_log_level = context.configuration.get_value(vdk_config.LOG_LEVEL_VDK)
+        if vdk_log_level is None:
+            vdk_log_level = logging.getLogger().getEffectiveLevel()
+        log_level_module = context.configuration.get_value(vdk_config.LOG_LEVEL_MODULE)
+
+        set_non_root_log_levels(vdk_log_level, log_level_module)
+
         metadata_keys = context.configuration.get_value(STRUCTLOG_LOGGING_METADATA_KEY)
         logging_formatter = context.configuration.get_value(
             STRUCTLOG_LOGGING_FORMAT_KEY
@@ -122,6 +138,23 @@ def initialize_job(self, context: JobContext) -> None:
         metadata_keys = context.core_context.configuration.get_value(
             STRUCTLOG_LOGGING_METADATA_KEY
         )
+        job_name = context.name
+        if logging.getLogger().getEffectiveLevel() == logging.NOTSET:
+            log_level = os.environ.get(
+                "LOG_LEVEL_VDK", os.environ.get("VDK_LOG_LEVEL_VDK", "INFO")
+            ).upper()
+            logging.getLogger().setLevel(log_level)
+        vdk_log_level = context.core_context.configuration.get_value(
+            vdk_config.LOG_LEVEL_VDK
+        )
+        if vdk_log_level is None:
+            vdk_log_level = logging.getLogger().getEffectiveLevel()
+        log_level_module = context.core_context.configuration.get_value(
+            vdk_config.LOG_LEVEL_MODULE
+        )
+
+        set_non_root_log_levels(vdk_log_level, log_level_module)
+
         logging_formatter = context.core_context.configuration.get_value(
             STRUCTLOG_LOGGING_FORMAT_KEY
         )
@@ -132,7 +165,7 @@ def initialize_job(self, context: JobContext) -> None:
         formatter, metadata_filter = create_formatter(
             logging_formatter, metadata_keys, custom_format_string
         )
-        job_name_adder = AttributeAdder("vdk_job_name", context.name)
+        job_name_adder = AttributeAdder("vdk_job_name", job_name)
 
         root_logger = logging.getLogger()
         root_logger.removeHandler(root_logger.handlers[0])
@@ -154,6 +187,23 @@ def run_job(self, context: JobContext) -> Optional[ExecutionResult]:
         metadata_keys = context.core_context.configuration.get_value(
             STRUCTLOG_LOGGING_METADATA_KEY
         )
+        job_name = context.name
+        if logging.getLogger().getEffectiveLevel() == logging.NOTSET:
+            log_level = os.environ.get(
+                "LOG_LEVEL_VDK", os.environ.get("VDK_LOG_LEVEL_VDK", "INFO")
+            ).upper()
+            logging.getLogger().setLevel(log_level)
+        vdk_log_level = context.core_context.configuration.get_value(
+            vdk_config.LOG_LEVEL_VDK
+        )
+        if vdk_log_level is None:
+            vdk_log_level = logging.getLogger().getEffectiveLevel()
+        log_level_module = context.core_context.configuration.get_value(
+            vdk_config.LOG_LEVEL_MODULE
+        )
+
+        set_non_root_log_levels(vdk_log_level, log_level_module)
+
         logging_formatter = context.core_context.configuration.get_value(
             STRUCTLOG_LOGGING_FORMAT_KEY
         )
@@ -164,7 +214,7 @@ def run_job(self, context: JobContext) -> Optional[ExecutionResult]:
         formatter, metadata_filter = create_formatter(
             logging_formatter, metadata_keys, custom_format_string
         )
-        job_name_adder = AttributeAdder("vdk_job_name", context.name)
+        job_name_adder = AttributeAdder("vdk_job_name", job_name)
 
         root_logger = logging.getLogger()
         root_logger.removeHandler(root_logger.handlers[0])

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

@@ -1,12 +1,23 @@
 # Copyright 2021-2023 VMware, Inc.
 # SPDX-License-Identifier: Apache-2.0
+import logging
 import os
 import re
 from unittest import mock
 
 import pytest
 from click.testing import Result
+from vdk.api.plugin.plugin_registry import IPluginRegistry
+from vdk.internal.builtin_plugins.config import vdk_config
+from vdk.internal.core.config import ConfigurationBuilder
+from vdk.internal.core.context import CoreContext
+from vdk.internal.core.errors import VdkConfigurationError
+from vdk.internal.core.statestore import StateStore
 from vdk.plugin.structlog import structlog_plugin
+from vdk.plugin.structlog.constants import STRUCTLOG_LOGGING_FORMAT_KEY
+from vdk.plugin.structlog.constants import STRUCTLOG_LOGGING_METADATA_KEY
+from vdk.plugin.structlog.log_level_utils import parse_log_level_module
+from vdk.plugin.structlog.structlog_plugin import StructlogPlugin
 from vdk.plugin.test_utils.util_funcs import CliEntryBasedTestRunner
 from vdk.plugin.test_utils.util_funcs import jobs_path_from_caller_directory
 
@@ -218,6 +229,76 @@ def _matches_custom_format(log):
     return bool(pattern.search(log))
 
 
+@pytest.mark.parametrize(
+    "log_type, vdk_level, expected_vdk_level",
+    (
+        ("LOCAL", "INFO", logging.INFO),
+        ("REMOTE", "WARNING", logging.WARNING),
+        ("LOCAL", None, logging.DEBUG),  # if not set default to root log level
+    ),
+)
+def test_log_plugin_structlog(log_type, vdk_level, expected_vdk_level):
+    logging.getLogger().setLevel(logging.DEBUG)  # root level
+    logging.getLogger("vdk").setLevel(logging.NOTSET)  # reset vdk log level
+
+    log_plugin = StructlogPlugin()
+
+    metadata_keys = "timestamp,level,file_name,line_number,vdk_job_name,bound_test_key,extra_test_key"
+    logging_format = "console"
+
+    store = StateStore()
+    conf = (
+        ConfigurationBuilder()
+        .add(vdk_config.LOG_CONFIG, log_type)
+        .add(vdk_config.LOG_LEVEL_VDK, vdk_level)
+        .add(STRUCTLOG_LOGGING_METADATA_KEY, metadata_keys)
+        .add(STRUCTLOG_LOGGING_FORMAT_KEY, logging_format)
+        .build()
+    )
+    core_context = CoreContext(mock.MagicMock(spec=IPluginRegistry), conf, store)
+
+    log_plugin.vdk_initialize(core_context)
+
+    assert logging.getLogger("vdk").getEffectiveLevel() == expected_vdk_level
+
+
+def test_parse_log_level_module_structlog():
+    assert parse_log_level_module("") == {}
+    assert parse_log_level_module("a.b.c=INFO") == {"a.b.c": {"level": "INFO"}}
+    assert parse_log_level_module("a.b.c=info") == {"a.b.c": {"level": "INFO"}}
+    assert parse_log_level_module("a.b.c=INFO;x.y=WARN") == {
+        "a.b.c": {"level": "INFO"},
+        "x.y": {"level": "WARN"},
+    }
+
+
+def test_parse_log_level_module_error_cases_structlog():
+    with pytest.raises(VdkConfigurationError):
+        parse_log_level_module("a.b.c=NOSUCH")
+
+    with pytest.raises(VdkConfigurationError):
+        parse_log_level_module("bad_separator_not_semi_colon=DEBUG,second_module=INFO")
+
+
+def test_log_plugin_exception_structlog():
+    with mock.patch(
+        "vdk.plugin.structlog.structlog_plugin.create_formatter"
+    ) as mocked_create_formatter:
+        mocked_create_formatter.side_effect = Exception("foo")
+
+        log_plugin = StructlogPlugin()
+
+        # Mock configuration since we won't be needing any.
+        core_context = mock.MagicMock(spec=CoreContext)
+        core_context.configuration = mock.MagicMock()
+        core_context.configuration.get_value.side_effect = (
+            lambda key: "INFO" if key == vdk_config.LOG_LEVEL_VDK else None
+        )
+        with pytest.raises(Exception) as exc_info:
+            log_plugin.vdk_initialize(core_context)
+        assert str(exc_info.value) == "foo", "Unexpected exception message"
+
+
 def _run_job_and_get_logs():
     """
     Runs the necessary job and returns the output logs.