Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

refactor logging #209

Draft
wants to merge 1 commit into
base: master
Choose a base branch
from
Draft

refactor logging #209

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions broker/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,3 @@
from broker.broker import Broker
#from broker.broker import Broker

VMBroker = Broker
#VMBroker = Broker
Comment on lines -1 to +3
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why comment these out?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good question.
I have checked out SatelliteQE/robottelo#1332 and installed broker from this PR/branch and I reverted the patch in this __init__.py file. I put breakpoint into both logger setup functions in broker and here is the call stack.

We can see that broker's logger gets initialized during the import time. That is not ideal, we want to initialize broker logger once setup_logger is called, not when it is imported.

from broker.logger import setup_logger as broker_log_setup import imports from broker.broker import Broker which imports from broker.hosts import Host which calls logger = init_logger(__name__) that initializes the logger.

Do you have any idea what could be a different approach to avoid setting the logger up during the import time?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's reframe this a bit.
Why try to avoid the initial logger setup?
What is gained from finding a way around it?
What is lost from user experience by implementing workarounds?

It's not always easy to do this in a way that satisfies what @rplevka wants here while maintaining a nice API and reducing waste. One potential option is for Broker to use its own logging wrapper that lazily sets up the logging interface.

Copy link
Member Author

@rplevka rplevka May 4, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi.
My primary motivation was to redesign broker logging in a way, so it can fully give away control over its setup to library that uses it (robottelo).
I was looking to setup different handlers (that would log to their own files) for different pytest objects - especially fixtures.
In pytest, it is possible to control this from the appropriate hook functions, however, these are being entered quite late in the process (by that time, the broker logger is self-initialized by mere module import - thus, it generates unwanted loggers and log files that are outside of robottelo control.

I don't have a strong opinion about how this is supposed to work, so I am opened to some ideas, but this design is something I came to while trying to solve a problem of a proper structured logging (to know what logs belong to what part of the session) for purposes of log parsing and pushing towards reporting platforms.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Due to import sequences, this isn't something that we can do easily in Python. In my opinion, it's not a big enough concern to justify changes like this. If Broker creates a log file and potentially a few logs before Robottelo redirects its logger, that's not a big deal. Please revert changes like the ones here.

4 changes: 3 additions & 1 deletion broker/broker.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,10 @@
from logzero import logger
from broker.providers import PROVIDERS, PROVIDER_ACTIONS, _provider_imports
from broker.hosts import Host
from broker import exceptions, helpers
from concurrent.futures import ThreadPoolExecutor, as_completed
from logging import getLogger

logger = getLogger('broker')

# load all the provider class so they are registered
for _import in _provider_imports:
Expand Down
4 changes: 3 additions & 1 deletion broker/commands.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,14 @@
import signal
import sys
import click
from logzero import logger
from logging import getLogger
from broker import exceptions, helpers, settings
from broker.broker import PROVIDERS, PROVIDER_ACTIONS, Broker
from broker.logger import LOG_LEVEL
from broker import exceptions, helpers, settings

logger = getLogger(__name__)
logger.propagate = True

signal.signal(signal.SIGINT, helpers.handle_keyboardinterrupt)

Expand Down
5 changes: 4 additions & 1 deletion broker/exceptions.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,8 @@
"""A collection of Broker-specific exceptions"""
from logzero import logger
from logging import getLogger

logger = getLogger(__name__)
logger.propagate = True


class BrokerError(Exception):
Expand Down
5 changes: 4 additions & 1 deletion broker/helpers.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,11 +15,14 @@
from uuid import uuid4

import yaml
from logzero import logger
from logging import getLogger

from broker import exceptions, settings
from broker import logger as b_log

logger = getLogger(__name__)
logger.propagate = True

FilterTest = namedtuple("FilterTest", "haystack needle test")


Expand Down
5 changes: 3 additions & 2 deletions broker/hosts.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,12 +1,13 @@
# from functools import cached_property
from logzero import logger
from broker.exceptions import NotImplementedError, HostError
from broker.session import ContainerSession, Session
from broker.settings import settings
from broker.logger import init_logger

logger = init_logger(__name__)
logger.propagate = True

class Host:

default_timeout = 0 # timeout in ms, 0 is infinite

def __init__(self, hostname=None, name=None, from_dict=False, **kwargs):
Expand Down
44 changes: 29 additions & 15 deletions broker/logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,6 @@ class LOG_LEVEL(IntEnum):
WARNING = logging.WARNING
ERROR = logging.ERROR


class RedactingFilter(logging.Filter):
"""Custom logging.Filter to redact secrets from the Dynaconf config"""
def __init__(self, sensitive):
Expand Down Expand Up @@ -55,12 +54,12 @@ def redact_dynaconf(self, data):
_sensitive = ["password", "pword", "token", "host_password"]
logging.addLevelName("TRACE", LOG_LEVEL.TRACE)
logzero.DEFAULT_COLORS[LOG_LEVEL.TRACE.value] = logzero.colors.Fore.MAGENTA
logger_prefix = ''

def patch_awx_for_verbosity(api):
client = api.client
awx_log = client.log

awx_log.parent = logzero.logger
#awx_log.parent = logzero.logger

def patch(cls, name):
func = getattr(cls, name)
Expand Down Expand Up @@ -130,21 +129,36 @@ def set_file_logging(level=settings.logging.file_level, path="logs/broker.log"):
)


def setup_logzero(
def setup_logger(
level=settings.logging.console_level,
formatter=None,
file_level=settings.logging.file_level,
name=None,
path="logs/broker.log",
path=None,
Comment on lines -138 to +137
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why default to none instead of Broker's default log path?

propagate=False,
):
urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning)
patch_awx_for_verbosity(awxkit.api)
set_log_level(level)
set_file_logging(file_level, path)
if formatter:
logzero.formatter(formatter)
logzero.logger.name = name or "broker"
logzero.logger.addFilter(RedactingFilter(_sensitive))


setup_logzero()
if formatter is None:
formatter = formatter_factory(level)
logger = logging.getLogger(name or 'broker')
logger.propagate = propagate
logger.setLevel(resolve_log_level(file_level))
logger.addFilter(RedactingFilter(_sensitive))
# cover logging to console
sh = logging.StreamHandler()
sh.setLevel(resolve_log_level(level))
logger.addHandler(sh)
# attach awxkit upstream logger to the hierarchy
awxkit.api.client.log.parent = logger

# used for attaching module-based loggers to hierarchy properly
global logger_prefix
logger_prefix = logger.parent.name+'.' if logger.parent.name != 'root' else ''
#set_log_level(level)
#set_file_logging(file_level, path)
#logzero.logger.name = name or "broker"
# logzero.logger.addFilter(RedactingFilter(_sensitive))

def init_logger(module):
return logging.getLogger(f'{logger_prefix}{module}')
# setup_logzero()
5 changes: 4 additions & 1 deletion broker/session.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,11 +2,14 @@
import socket
import tempfile
from pathlib import Path
from logzero import logger
from logging import getLogger
from ssh2.session import Session as ssh2_Session
from ssh2 import sftp as ssh2_sftp
from broker import helpers

logger = getLogger(__name__)
logger.propagate = True

SESSIONS = {}

SFTP_MODE = (
Expand Down