Fix configuring loggers found in 'PREFECT_LOGGING_EXTRA_LOGGERS'

[estasney]

Each logger defined in 'PREFECT_LOGGING_EXTRA_LOGGERS' now has their level set according to the 'prefect.extra' level. Previously, this only occurred when their level was NOTSET.

Additionally, avoid configuring the logger 'level' and 'propagate' values while iterating over 'extra_config.handlers'

closes #15370

Checklist

• This pull request references any related issue by including "closes <link to issue>"
  • If no issue exists and your change is not a small fix, please create an issue first.
• If this pull request adds new functionality, it includes unit tests that cover the changes
• If this pull request removes docs files, it includes redirect settings in mint.json.
• If this pull request adds functions or classes, it includes helpful docstrings.

[codspeed-hq]

CodSpeed Performance Report

Merging #16652 will not alter performance

_{Comparing estasney:fix-configuring-extra-loggers (d8d196d) with main (6b560c8)}

Summary

✅ 2 untouched benchmarks

[j-carson]

I added a note to the issue, but this was not the change I wanted to do -- I wanted the level to be set on the handler which prefect owns and creates in this function, not on the logger, which belongs to some other library and may have other handlers on it.

[j-carson]

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.

[estasney]

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

[j-carson]

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.

[zzstoatzz]

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)

[zzstoatzz]

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

[estasney]

@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

[j-carson]

@zzstoatzz Yes, this is what I was asking for

[estasney]

Added test_setup_logging_extra_loggers_does_not_modify_external_logger_level
Squashed the commits and merges from main
Removed logger.propagate = extra_config.propagate since this would be mutating an external logger which is not desired

[zzstoatzz]

thank you @estasney - nice test!