Skip to content

Commit

Permalink
vdk-core: ensure early logs are available
Browse files Browse the repository at this point in the history
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)
  • Loading branch information
antoniivanov committed Oct 27, 2023
1 parent cf762f6 commit b52cebf
Show file tree
Hide file tree
Showing 3 changed files with 35 additions and 3 deletions.
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -68,11 +68,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,
Expand Down
5 changes: 4 additions & 1 deletion projects/vdk-core/src/vdk/internal/cli_entry.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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()
Expand Down

0 comments on commit b52cebf

Please sign in to comment.