diff --git a/projects/vdk-core/src/vdk/internal/builtin_plugins/config/log_config.py b/projects/vdk-core/src/vdk/internal/builtin_plugins/config/log_config.py index d06bbeeae1..40b190bd3e 100644 --- a/projects/vdk-core/src/vdk/internal/builtin_plugins/config/log_config.py +++ b/projects/vdk-core/src/vdk/internal/builtin_plugins/config/log_config.py @@ -1,6 +1,7 @@ # Copyright 2021 VMware, Inc. # SPDX-License-Identifier: Apache-2.0 import logging +import re import socket import types from sys import modules @@ -11,6 +12,7 @@ from vdk.internal.builtin_plugins.run.job_context import JobContext from vdk.internal.core import errors from vdk.internal.core.config import ConfigurationBuilder +from vdk.internal.core.errors import ResolvableBy from vdk.internal.core.statestore import CommonStoreKeys SYSLOG_URL = "SYSLOG_URL" @@ -21,11 +23,54 @@ SYSLOG_SOCK_TYPE_VALUES_DICT = {"UDP": socket.SOCK_DGRAM, "TCP": socket.SOCK_STREAM} +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 in {valid_logging_levels} " + ) + result[module_and_level[0]] = {"level": module_and_level[1].upper()} + return result + else: + return {} + except Exception as e: + errors.log_and_throw( + ResolvableBy.CONFIG_ERROR, + logging.getLogger(__name__), + "Invalid logging configuration passed to LOG_LEVEL_MODULE.", + f"Error is: {e}. log_level_module was set to {log_level_module}.", + "Logging will not be initialized and exception is raised", + "Set correctly configuration to log_level_debug configuration in format 'module=level,module2=level2'", + ) + + def configure_loggers( job_name: str = "", attempt_id: str = "no-id", log_config_type: str = None, vdk_logging_level: str = "DEBUG", + log_level_module: str = None, syslog_args: (str, int, str, bool) = ("localhost", 514, "UDP", False), ) -> None: """ @@ -35,6 +80,7 @@ def configure_loggers( :param attempt_id: the id of the current job run attempt :param log_config_type: where the job is executed: CLOUD or LOCAL :param vdk_logging_level: The level for vdk specific logs. + :param log_level_module: The level for modules specific logs :param syslog_args: Arguments necessary for SysLog logging. """ @@ -59,6 +105,7 @@ def configure_loggers( "urllib3": {"level": "INFO"}, "vdk": {"level": vdk_logging_level}, } + _LOGGERS.update(_parse_log_level_module(log_level_module)) _FORMATTERS = {"detailedFormatter": {"format": DETAILED_FORMAT}} @@ -202,6 +249,9 @@ def initialize_job(self, context: JobContext) -> None: vdk_log_level = context.core_context.configuration.get_value( vdk_config.LOG_LEVEL_VDK ) + log_level_module = context.core_context.configuration.get_value( + vdk_config.LOG_LEVEL_MODULE + ) syslog_url = context.core_context.configuration.get_value(SYSLOG_URL) syslog_port = context.core_context.configuration.get_value(SYSLOG_PORT) syslog_sock_type = context.core_context.configuration.get_value( @@ -214,6 +264,7 @@ def initialize_job(self, context: JobContext) -> None: attempt_id, log_config_type=log_config_type, vdk_logging_level=vdk_log_level, + log_level_module=log_level_module, syslog_args=(syslog_url, syslog_port, syslog_sock_type, syslog_enabled), ) log = logging.getLogger(__name__) diff --git a/projects/vdk-core/src/vdk/internal/builtin_plugins/config/vdk_config.py b/projects/vdk-core/src/vdk/internal/builtin_plugins/config/vdk_config.py index 349aab047c..0592529ff5 100644 --- a/projects/vdk-core/src/vdk/internal/builtin_plugins/config/vdk_config.py +++ b/projects/vdk-core/src/vdk/internal/builtin_plugins/config/vdk_config.py @@ -18,6 +18,7 @@ JOB_GITHASH = "JOB_GITHASH" LOG_CONFIG = "LOG_CONFIG" LOG_LEVEL_VDK = "LOG_LEVEL_VDK" +LOG_LEVEL_MODULE = "LOG_LEVEL_MODULE" WORKING_DIR = "WORKING_DIR" ATTEMPT_ID = "ATTEMPT_ID" EXECUTION_ID = "EXECUTION_ID" @@ -69,6 +70,16 @@ def vdk_configure(self, config_builder: ConfigurationBuilder) -> None: "Allowed values: CRITICAL, ERROR, WARNING, INFO, DEBUG. " "If not set python default or one set by vdk -v LEVEL is used. ", ) + config_builder.add( + LOG_LEVEL_MODULE, + None, + True, + "Logging verbosity of specific module can be controlled from here." + "Format is semi colon separated list of module and level." + " module=level,module2=level2 For example a.b.c=INFO;foo.bar=ERROR " + "Allowed values: CRITICAL, ERROR, WARNING, INFO, DEBUG. " + "If not set python default or one set by vdk -v LEVEL is used. ", + ) config_builder.add(JOB_GITHASH, "unknown") config_builder.add( OP_ID, diff --git a/projects/vdk-core/tests/vdk/internal/builtin_plugins/config/test_log_config.py b/projects/vdk-core/tests/vdk/internal/builtin_plugins/config/test_log_config.py index 05135e140a..cfdc82d712 100644 --- a/projects/vdk-core/tests/vdk/internal/builtin_plugins/config/test_log_config.py +++ b/projects/vdk-core/tests/vdk/internal/builtin_plugins/config/test_log_config.py @@ -3,10 +3,14 @@ import logging import pathlib from unittest import mock +from unittest.mock import patch import pytest from vdk.api.plugin.plugin_registry import IPluginRegistry +from vdk.internal.builtin_plugins.config import log_config from vdk.internal.builtin_plugins.config import vdk_config +from vdk.internal.builtin_plugins.config.log_config import _parse_log_level_module +from vdk.internal.builtin_plugins.config.log_config import configure_loggers from vdk.internal.builtin_plugins.config.log_config import LoggingPlugin from vdk.internal.builtin_plugins.config.log_config import SYSLOG_ENABLED from vdk.internal.builtin_plugins.config.log_config import SYSLOG_PORT @@ -17,6 +21,7 @@ from vdk.internal.builtin_plugins.templates.template_impl import TemplatesImpl 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 CommonStoreKeys from vdk.internal.core.statestore import StateStore @@ -66,3 +71,34 @@ def test_log_plugin(log_type, vdk_level, expected_vdk_level): assert ( logging.getLogger("vdk").getEffectiveLevel() == expected_vdk_level ), "internal vdk logs must be set according to configuration option LOG_LEVEL_VDK but are not" + + +def test_parse_log_level_module(): + 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(): + 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_configure_logger(): + with patch("logging.config.dictConfig") as mock_dict_config: + with patch.object(log_config, "_set_already_configured"): + configure_loggers( + job_name="job-name", + attempt_id="attempt-id", + log_level_module="a.b.c=INFO;foo.bar=ERROR", + ) + configured_loggers = mock_dict_config.mock_calls[0].args[0]["loggers"] + assert configured_loggers["a.b.c"]["level"] == "INFO" + assert configured_loggers["foo.bar"]["level"] == "ERROR"