Skip to content

Fix configuring loggers found in 'PREFECT_LOGGING_EXTRA_LOGGERS' #16652

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

Merged
zzstoatzz merged 1 commit into from
Jan 21, 2025
Merged

Fix configuring loggers found in 'PREFECT_LOGGING_EXTRA_LOGGERS' #16652

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
7 changes: 2 additions & 5 deletions src/prefect/logging/configuration.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -94,12 +94,9 @@ def setup_logging(incremental: Optional[bool] = None) -> dict[str, Any]:

for logger_name in PREFECT_LOGGING_EXTRA_LOGGERS.value():
logger = logging.getLogger(logger_name)
for handler in extra_config.handlers:
if not config["incremental"]:
if not config["incremental"]:
for handler in extra_config.handlers:
logger.addHandler(handler)
if logger.level == logging.NOTSET:
logger.setLevel(extra_config.level)
logger.propagate = extra_config.propagate
Copy link

@j-carson j-carson Jan 16, 2025

Choose a reason for hiding this comment

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

Does it not work if this code were changed to:

handler.setLevel(extra_config.level) instead of logger.setLevel(extra_config.level) ?

Again, my motivation on creating the original issue is that non-prefect libraries may not know about the "extra_config.level" parameter and may have other mechanisms for setting up their own logging config. IMO, Prefect's handler should be more like an add on not a replacement.

Copy link
Contributor Author

@estasney estasney Jan 17, 2025

Choose a reason for hiding this comment

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

Lets assume we're using the logging.yml prefect uses. I'm also assuming non-prefect libraries follow the logging guidelines (IME most do) Python Logging

A library will typically do

logger.debug('User doesn't care about this')
logger.warning('User care's about this')

If I run a flow, I'll see the warning in the prefect ui, but not the debug. debug > notset. Assuming above, the libraries logger does not have its level set and defers to the root logger (warning).

What I'm proposing won't interfere with libraries logging config. It will only adjust how the user (us) receive them

Copy link

@j-carson j-carson Jan 17, 2025

Choose a reason for hiding this comment

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

But what if the handler set up by prefect isn't the only handler?

This issue came about because my library can create two handlers -- one at level debug to write to a log file and one at level warning to write to the console.

So for logger = logging.getLogger("myLib")

logger.debug - goes to one handler

logger.warning - matches two handlers

I was trying to make my prefect UI logger match what my console logger does today. The way I achieve that right now is:

logger.setLevel('debug')
for each handler in logger.getHandlers(), search for prefect's handler
handler.addFilter(my_filter_function)

where my_filter_function does not forward the debug level stuff up to the UI

This hack is dependent on the order in which library imports happen - because the parent level logger could be set by prefect or by my library depending on who's initializer runs first.

In my opinion, the prefect "extra logging level" should configure only prefect's handler object, not to the entire logger object.

Copy link
Collaborator

@zzstoatzz zzstoatzz Jan 17, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

Thanks @estasney and @j-carson for articulating your positions!

After chatting a bit with @desertaxle, we agree we're doing the wrong thing by modifying external loggers' levels. We should probably only configure our own handlers:

# In setup_logging():
for logger_name in PREFECT_LOGGING_EXTRA_LOGGERS.value():
    logger = logging.getLogger(logger_name)
    for handler in extra_config.handlers:
        if not config["incremental"]:
            handler.setLevel(extra_config.level)  # Only set level on our handler
            logger.addHandler(handler)
        logger.propagate = extra_config.propagate

This would technically be a breaking change but it's arguably more correct - we should only configure our own handlers, not override library logging levels.

What do you think @estasney? (sounds like this is what you were opting for @j-carson - feel free to correct me)

Copy link
Collaborator

@zzstoatzz zzstoatzz Jan 17, 2025

Choose a reason for hiding this comment

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

as a side note, please use pre-commit install before your next commit to avoid the static analysis errors

https://docs.prefect.io/contribute/dev-contribute#install-prefect-for-development

Copy link
Contributor Author

@estasney estasney Jan 17, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

@j-carson I see your point, and this is an interesting problem. I suppose my perspective was more geared towards favoring logging logic being defined in the deployment vs in code. I will remove the bit about setting external loggers.

@zzstoatzz Thanks for reviewing! Just want to point out that

handler.setLevel(extra_config.level)

May appear to cause side effects

  api:
    level: 0  
    class: prefect.logging.handlers.APILogHandler
    
  prefect.extra:
    level: "${PREFECT_LOGGING_LEVEL}"
    handlers: [api]
    propagate: false

But would effectively become (after running setup_logging)

  api:
    level: "${PREFECT_LOGGING_LEVEL}" 
    class: prefect.logging.handlers.APILogHandler
    
  prefect.extra:
    level: "${PREFECT_LOGGING_LEVEL}"
    handlers: [api]
    propagate: false

If the goal is not to modify the level of external loggers should we also extend that to the propagate property? I.e. don't modify external loggers propagate

Sorry I missed the pre-commit install I'll fix that now

I'll move this a draft PR as I also want to add a test

Copy link

@j-carson j-carson Jan 17, 2025

Choose a reason for hiding this comment

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

@zzstoatzz Yes, this is what I was asking for


PROCESS_LOGGING_CONFIG = config

Expand Down
61 changes: 61 additions & 0 deletions tests/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@
from prefect.settings import (
PREFECT_API_KEY,
PREFECT_LOGGING_COLORS,
PREFECT_LOGGING_EXTRA_LOGGERS,
PREFECT_LOGGING_LEVEL,
PREFECT_LOGGING_MARKUP,
PREFECT_LOGGING_SETTINGS_PATH,
Expand Down Expand Up @@ -222,6 +223,66 @@ def test_default_level_is_applied_to_interpolated_yaml_values(dictConfigMock):
dictConfigMock.assert_called_once_with(expected_config)


@pytest.fixture()
def external_logger_setup(request):
# This fixture will create a logger with the specified name, level, and propagate value
name, level = request.param
logger = logging.getLogger(name)
old_level, old_propagate = logger.level, logger.propagate
assert logger.level == logging.NOTSET, "Logger should start with NOTSET level"
assert logger.handlers == [], "Logger should start with no handlers"
logger.setLevel(level)
yield name, level, old_propagate
# Reset the logger to its original state
logger.setLevel(old_level)
logger.propagate = old_propagate
logger.handlers = []


@pytest.mark.parametrize(
"external_logger_setup",
[
("foo", logging.DEBUG),
("foo.child", logging.DEBUG),
("foo", logging.INFO),
("foo.child", logging.INFO),
("foo", logging.WARNING),
("foo.child", logging.WARNING),
("foo", logging.ERROR),
("foo.child", logging.ERROR),
("foo", logging.CRITICAL),
("foo.child", logging.CRITICAL),
],
indirect=True,
ids=lambda x: f"logger='{x[0]}'-level='{logging.getLevelName(x[1])}'",
)
def test_setup_logging_extra_loggers_does_not_modify_external_logger_level(
dictConfigMock, external_logger_setup
):
ext_name, ext_level, ext_propagate = external_logger_setup
with temporary_settings(
{
PREFECT_LOGGING_LEVEL: "WARNING",
PREFECT_TEST_MODE: False,
PREFECT_LOGGING_EXTRA_LOGGERS: ext_name,
}
):
expected_config = load_logging_config(DEFAULT_LOGGING_SETTINGS_PATH)
expected_config["incremental"] = False
setup_logging()

dictConfigMock.assert_called_once_with(expected_config)
external_logger = logging.getLogger(ext_name)
assert external_logger.level == ext_level, "External logger level was not preserved"
if ext_level > logging.NOTSET:
assert external_logger.isEnabledFor(
ext_level
), "External effective level was not preserved"
assert (
external_logger.propagate == ext_propagate
), "External logger propagate was not preserved"


@pytest.fixture
def mock_log_worker(monkeypatch):
mock = MagicMock()
Expand Down
Loading