vdk-core: vdk run logging levels (#483)

`vdk -v LEVEL` can be used to set logging level. But during vdk run this
was overriden by default levels set when configuring loggers. So `vdk -v
LEVEL` was not really working. This fixes that.

Logs of the vdk namespaces can also be controled by separate configu
LOG_LEVEL_VDK. It is set to INFO by default.

Testing Done: ran `vdk -v DEBUG run example-job` and `vdk run
example-job` and saw expected logs

Signed-off-by: Antoni Ivanov <[email protected]>

projects/vdk-core/cicd/example-job/30_check_orders_table.py

@@ -5,19 +5,22 @@
 """
 import logging
 
+log = logging.getLogger(__name__)
+
 
 def run(job_input):
     """
     This method is called automatically during execution. Only scripts containing this method are executed by VDK.
        Arguments:
           job_input: object automatically passed to run() method by VDK on execution.
     """
+    log.debug(f"Start data job step {__name__}.")
     result = job_input.execute_query(
         """
       select count(1) from orders
    """
     )
     if result and result[0][0] > 0:
-        logging.getLogger(__name__).info("Job has completed successfully")
+        log.info("Job has completed successfully")
     else:
         raise Exception("Job has failed. Could not get correct number of rows.")

projects/vdk-core/src/vdk/internal/builtin_plugins/config/log_config.py

@@ -48,14 +48,13 @@ def configure_loggers(
         "requests_kerberos": {"level": "INFO"},
         "requests_oauthlib": {"level": "INFO"},
         "urllib3": {"level": "INFO"},
-        "taurus": {"level": vdk_logging_level},
+        "vdk": {"level": vdk_logging_level},
     }
 
     _FORMATTERS = {"detailedFormatter": {"format": DETAILED_FORMAT}}
 
     _CONSOLE_HANDLER = {
         "class": "logging.StreamHandler",
-        "level": "DEBUG",
         "formatter": "detailedFormatter",
         "stream": "ext://sys.stderr",
     }
@@ -65,7 +64,7 @@ def configure_loggers(
             "version": 1,
             "handlers": {"consoleHandler": _CONSOLE_HANDLER},
             "formatters": _FORMATTERS,
-            "root": {"handlers": ["consoleHandler"], "level": "INFO"},
+            "root": {"handlers": ["consoleHandler"]},
             "loggers": _LOGGERS,
             "disable_existing_loggers": False,
         }
@@ -77,7 +76,7 @@ def configure_loggers(
             "version": 1,
             "handlers": {"consoleHandler": _CONSOLE_HANDLER},
             "formatters": _FORMATTERS,
-            "root": {"handlers": ("consoleHandler",), "level": "DEBUG"},
+            "root": {"handlers": ("consoleHandler",)},
             "loggers": _LOGGERS,
             "disable_existing_loggers": False,
         }

projects/vdk-core/src/vdk/internal/builtin_plugins/config/vdk_config.py

@@ -62,9 +62,10 @@ def vdk_configure(self, config_builder: ConfigurationBuilder) -> None:
         )  # {LOCAL, CLOUD, NONE} To be overridden when executing in cloud
         config_builder.add(
             LOG_LEVEL_VDK,
-            "DEBUG",
+            None,
             "Logging verbosity of VDK code can be controlled from here. "
-            "Allowed values: CRITICAL, ERROR, WARNING, INFO, DEBUG",
+            "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(

projects/vdk-core/tests/functional/run/test_run_configuration.py

@@ -1,5 +1,6 @@
 # Copyright 2021 VMware, Inc.
 # SPDX-License-Identifier: Apache-2.0
+import logging
 import os
 from typing import Optional
 from unittest import mock
@@ -43,3 +44,26 @@ def run_job(self, context: JobContext) -> Optional[ExecutionResult]:
 
     cli_assert_equal(0, result)
     assert actual_ids == ["my-attempt-id", "my-execution-id", "my-op-id"]
+
+
+def test_run_check_log_level_configured_correctly():
+    debug_log_message = "DEBUG LOG 1123581321"
+
+    class DummyDebugLog:
+        @hookimpl(tryfirst=True)
+        def run_job(self, context: JobContext) -> Optional[ExecutionResult]:
+            # -v may not apply to vdk packages which are controlled separately
+            logging.getLogger("other").debug(debug_log_message)
+            return None  # continue with next hook impl.
+
+    runner = CliEntryBasedTestRunner(DummyDebugLog())
+
+    # -v DEBUG means we print debug logs
+    result: Result = runner.invoke(["-v", "DEBUG", "run", util.job_path("simple-job")])
+    cli_assert_equal(0, result)
+    assert debug_log_message in result.output
+
+    # -v INFO - debug logs should not be printed.
+    result: Result = runner.invoke(["-v", "INFO", "run", util.job_path("simple-job")])
+    cli_assert_equal(0, result)
+    assert debug_log_message not in result.output

projects/vdk-core/tests/vdk/internal/builtin_plugins/config/test_log_config.py

@@ -20,13 +20,17 @@
 
 
 @pytest.mark.parametrize(
-    "log_type, level, expected_level",
+    "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(log_type, level, expected_level):
+def test_log_plugin(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 = LoggingPlugin()
 
     store = StateStore()
@@ -35,7 +39,7 @@ def test_log_plugin(log_type, level, expected_level):
     conf = (
         ConfigurationBuilder()
         .add(vdk_config.LOG_CONFIG, log_type)
-        .add(vdk_config.LOG_LEVEL_VDK, level)
+        .add(vdk_config.LOG_LEVEL_VDK, vdk_level)
         .build()
     )
     core_context = CoreContext(MagicMock(spec=IPluginRegistry), conf, store)
@@ -51,5 +55,5 @@ def test_log_plugin(log_type, level, expected_level):
     log_plugin.initialize_job(job_context)
 
     assert (
-        logging.getLogger("taurus").getEffectiveLevel() == expected_level
+        logging.getLogger("vdk").getEffectiveLevel() == expected_vdk_level
     ), "internal vdk logs must be set according to configuration option LOG_LEVEL_VDK but are not"