vdk-core: ensure early logs are available

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

@@ -1,6 +1,7 @@
 # Copyright 2021-2023 VMware, Inc.
 # SPDX-License-Identifier: Apache-2.0
 import logging
+import os
 import re
 import socket
 import types
@@ -9,6 +10,7 @@
 
 from vdk.api.plugin.hook_markers import hookimpl
 from vdk.internal.builtin_plugins.config import vdk_config
+from vdk.internal.builtin_plugins.config.vdk_config import LOG_LEVEL_VDK
 from vdk.internal.builtin_plugins.run.job_context import JobContext
 from vdk.internal.core import errors
 from vdk.internal.core.config import ConfigurationBuilder
@@ -65,6 +67,30 @@ def _parse_log_level_module(log_level_module):
         )
 
 
+def configure_initial_logging_before_anything():
+    """
+    Configure logging at the start of the app.
+    At this point we do not know what user has configured so we use some sensible approach
+    All logs would be vdk only logs. User code will not have been executed yet so we will use log_level_vdk
+    to control the level.
+    We default to WARN since in most cases users would not care about internal vdk logs.
+
+    Logging lifecycle:
+    1. This function is executed at the entry point of the app and configures default logging format and level
+    2. After vdk_initialize hook is executed and CLI command starts then `vdk --verbosity` option is taken (if set)
+        and click logging configuration takes over
+    3. When initialize_job hook (applicable for vdk run only) is executed then below configure_loggers function
+        is run which adds more context to the logs and initializes syslog handler (if configured to do so)
+    """
+    log_level = "WARNING"
+    if os.environ.get(LOG_LEVEL_VDK, None):
+        log_level = os.environ.get(LOG_LEVEL_VDK)
+    elif os.environ.get("VDK_LOG_LEVEL_VDK", None):
+        log_level = os.environ.get("VDK_LOG_LEVEL_VDK")
+
+    logging.basicConfig(format="%(message)s", level=logging.getLevelName(log_level))
+
+
 def configure_loggers(
     job_name: str = "",
     attempt_id: str = "no-id",

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

@@ -69,11 +69,14 @@ def vdk_configure(self, config_builder: ConfigurationBuilder) -> None:
         )  # {LOCAL, CLOUD, NONE} To be overridden when executing in cloud
         config_builder.add(
             LOG_LEVEL_VDK,
-            None,
+            "INFO",
             True,
             "Logging verbosity of VDK code can be controlled from here. "
             "Allowed values: CRITICAL, ERROR, WARNING, INFO, DEBUG. "
-            "If not set python default or one set by vdk -v LEVEL is used. ",
+            "If not set python default is used. vdk -v <LEVEL> would take precedence over this variable."
+            "LOG_LEVEL_VDK environment variable is used when the CLI is starting as initial logging level "
+            "before any configuration is loaded. "
+            "Afterwards -v <LEVEL> is considered and vdk loaded configuration.",
         )
         config_builder.add(
             LOG_LEVEL_MODULE,

projects/vdk-core/src/vdk/internal/cli_entry.py

@@ -13,6 +13,9 @@
 from vdk.api.plugin.hook_markers import hookimpl
 from vdk.api.plugin.plugin_registry import IPluginRegistry
 from vdk.internal.builtin_plugins import builtin_hook_impl
+from vdk.internal.builtin_plugins.config.log_config import (
+    configure_initial_logging_before_anything,
+)
 from vdk.internal.builtin_plugins.internal_hookspecs import InternalHookSpecs
 from vdk.internal.core.config import Configuration
 from vdk.internal.core.config import ConfigurationBuilder
@@ -170,7 +173,7 @@ def main() -> None:
     This the starting point for the Python vdk console script.
     """
     # configure basic logging , it's expected that a plugin would override and set it up properly
-    click_log.basic_config(logging.getLogger())
+    configure_initial_logging_before_anything()
 
     log.debug("Setup plugin registry and call vdk_start hooks ...")
     plugin_registry = PluginRegistry()