vdk-core: ensure early logs are available (#2846)

When vdk command is started logs do not really show up until click
command start getting executed. All logs before that (from plugin hooks)
seemed ignored.

I couldn't figure out for sure while click_log does that.

But this changes it so that early logs can be seen on console . The log
level of the early logs is controlled by LOG_LEVEL_VDK option (which
control the log level of VDK logs , since early logs are really vdk logs
it make sense)

By default LOG_LEVEL_VDK is WARNING, so if more verbose logs are set it
should be changed to INFO.

Testing Done:
```
export LOG_LEVEL_VDK=INFO
vdk run example
```
logs look like
https://gist.github.com/antoniivanov/bdd935927c1149b74944c58e96b50ee3

```
unset LOG_LEVEL_VDK
vdk run example
```
logs look like
https://gist.github.com/antoniivanov/afce585f8cd03ac4e09e9010dcdd2b9a

Tested also with vdk -v DEBUG ... to see debug logs show up correctly
(with bot set and unset LOG_LEVEL_VDK)

Tested other commands vdk deploy, login, info that logs look like before
(aka no unnecessary logs)

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()