Initialize logging system at ROOT vs limiting to dynatrace_extension.sdk.extension and api

[JosephHobbs]

Is your feature request related to a problem? Please describe.

The current extension logging initialization only adds handlers to the 'dynatrace_extension.sdk.extension' and 'api' loggers. Due to this, other modules do not get these appenders, which prevents logs from being written for any logger outside of these two. This means that any logging I do in my own modules does not show up by default.

Describe the solution you'd like

I would love to see these appenders attached to the ROOT logger. This will ensure that all loggers would send their logs to these appenders as opposed to just the two built-in loggers. So for example, changing...

formatter = logging.Formatter("%(asctime)s [%(levelname)s] %(name)s (%(threadName)s): %(message)s")
error_handler = logging.StreamHandler()
error_handler.addFilter(lambda record: record.levelno >= logging.ERROR)
error_handler.setFormatter(formatter)
std_handler = logging.StreamHandler(sys.stdout)
std_handler.addFilter(lambda record: record.levelno < logging.ERROR)
std_handler.setFormatter(formatter)
extension_logger = logging.getLogger(__name__)
extension_logger.setLevel(logging.INFO)
extension_logger.addHandler(error_handler)
extension_logger.addHandler(std_handler)

api_logger = logging.getLogger("api")
api_logger.setLevel(logging.INFO)
api_logger.addHandler(error_handler)
api_logger.addHandler(std_handler)

to something like this...

formatter = logging.Formatter("%(asctime)s [%(levelname)s] %(name)s (%(threadName)s): %(message)s")
error_handler = logging.StreamHandler()
error_handler.addFilter(lambda record: record.levelno >= logging.ERROR)
error_handler.setFormatter(formatter)
std_handler = logging.StreamHandler(sys.stdout)
std_handler.addFilter(lambda record: record.levelno < logging.ERROR)
std_handler.setFormatter(formatter)

logging.getLogger().addHandler(error_handler)
logging.getLogger().addHandler(std_handler)

extension_logger = logging.getLogger(__name__)
extension_logger.setLevel(logging.INFO)

api_logger = logging.getLogger("api")
api_logger.setLevel(logging.INFO)

Describe alternatives you've considered

At this point, my workaround/alternative is to duplicate your logging code within my own init.py. This (at least) initializes the logger for my extension (module) and would apply to that module down...

################################################################################
# __init__.py
################################################################################

import logging
import sys

# The 'internal' name of our extension

EXTENSION_NAME = '%extension_name%'

# Initialize a logger for our extension namespace so that everything within
# the namespace will output to the log file! This is the same initialization
# code Dynatrace is using within their SDK.

_logging_formatter = logging.Formatter(
    "%(asctime)s [%(levelname)s] %(name)s (%(threadName)s): %(message)s")

_logging_handler_err = logging.StreamHandler()
_logging_handler_err.addFilter(lambda record: record.levelno >= logging.ERROR)
_logging_handler_err.setFormatter(_logging_formatter)

_logging_handler_out = logging.StreamHandler(sys.stdout)
_logging_handler_out.addFilter(lambda record: record.levelno < logging.ERROR)
_logging_handler_out.setFormatter(_logging_formatter)

_extension_logger = logging.getLogger(EXTENSION_NAME)
_extension_logger.setLevel(logging.INFO)
_extension_logger.addHandler(_logging_handler_err)
_extension_logger.addHandler(_logging_handler_out)

################################################################################
# END
################################################################################

[radu-stefan-dt]

Why not reuse the same logger?

from dynatrace_extension.sdk.extension import extension_logger as logger

logger.info("Hello world")

[JosephHobbs]

I'd argue against reusing the same logger for a couple of reasons...

1. If I wrote python anywhere other than for a Dynatrace extension, that (reusing a child logger) is not how I'd do it...
2. The dependency is the wrong way. You're importing your module INTO the extension implementation for use. Having that module then reach back to the extension using said module seems cyclical...
3. While I could do this to address logging for MY extension implementation, it won't give me logs for any other 3rd library I might be using if I need them.

I'm happy to update/submit the PR if this makes sense. I just didn't want to make a foundational change like this and submit it without at least having this conversation. :-)

[dlopes7]

Won't your idea affect all the 200+ existing extensions? Adding log lines from third party dependencies without the developer explicitly asking for it?

[dlopes7]

I agree that importing the logger from dynatrace_extension is not a good idea, your modules should not depend on dynatrace_extension

What I think you should have though is a way for your modules to receive a logging.Logger object, ie in the constructor of a class, so that you can pass the extension self.logger to your module if you so desire

This is done extensively by many third party libraries and extensions

[JosephHobbs]

Won't your idea affect all the 200+ existing extensions? Adding log lines from third party dependencies without the developer explicitly asking for it?

No. This does not change the root logger's level at all... All it does is give loggers a handler that actually writes logs somewhere when that specific logger is enabled...

[JosephHobbs]

I agree that importing the logger from dynatrace_extension is not a good idea, your modules should not depend on dynatrace_extension

What I think you should have though is a way for your modules to receive a logging.Logger object, ie in the constructor of a class, so that you can pass the extension self.logger to your module if you so desire

This is done extensively by many third party libraries and extensions

This is definitely a workaround I could use for my own custom module, but it's still not the greatest option. It means I can only manage the logging level of the primary logger versus being able to control log levels for my extension and submodule independently. All logs from my submodule will be logged as if reside in the primary extension module. It also means I'll still NOT get any logging data from any 3rd party module I enable debug for...

[dlopes7]

Won't your idea affect all the 200+ existing extensions? Adding log lines from third party dependencies without the developer explicitly asking for it?

No. This does not change the root logger's level at all... All it does is give loggers a handler that actually writes logs somewhere when that specific logger is enabled...

I didn't mean that this changes the root logger level.

What I am saying is that other libraries writing to the root logger will now be logged to the extension log

[dlopes7]

We don't want to automatically start logging from other libraries, even if they write info level, this is a change to too many extensions at once

[JosephHobbs]

This proposal will not cause that. Python's default logging level is WARN. The only loggers you are currently setting to INFO are the extension and api loggers.

[JosephHobbs]

If even WARN is a concern, we could increase the root logger to CRITICAL to keep all but the most critical items from being logged. This would abate much of the 'sudden new logs' risk while also providing extensions a fully functioning logger implementation.

[JosephHobbs]

If it helps, one of the guiding principals of python logging PEP-282 is specifically avoid having to pass around loggers.

https://peps.python.org/pep-0282/#:~:text=one%20does%20not%20have%20to%20pass%20logger%20object%20references%20around.

:-)