Address logging test failures #173
Comments
|
I was able to reproduce the case with just one test failure locally. However, when I tried running this test again with debug output and alone (via Edit 1: running all Edit 2: I now started checking when I would see a test failure as above. Running Edit 3: In line 51 of loggers = [logging.getLogger(name) for name in logging.root.manager.loggerDict]
print(loggers)and compared the output of the failed test and the successful one (for which I had to include an
Then, everything stays the same until The tangent |
|
Okay, that's great detective work to narrow it down. To be clear, every Logger object can have 0 or more Handlers attached. Messages from, say, Each logger, if it chooses to handle the message, uses its own respective Handlers. In each case, if the level of the message (eg DEBUG) is lower than the level set on that Logger (eg WARNING), then handling stops. The root Logger is where message-ix-models, as a user-facing application, attaches its handlers, filters, etc. So we can next look to see whether these are disturbed in the failing case; this will probably be a side effect of one of the packages listed in the 'tangent'. |
|
I've tried the following: (1) Run
(2) Add a debugging function in test_report.py, roughly like this: def show_log_handlers(id: int):
import logging
from icecream import ic
root_logger = logging.getLogger("root")
ic(id, root_logger.level, root_logger.handlers)(3) Added calls to this function in each of the 4 tests: at least at the top and bottom, or maybe in more places. This gives the following results (abbreviated): So this tells me it is somewhere between the points "test_report_bare_res 0" and "test_report_bare_res 1" where the message-ix-models handlers get wiped out. I'll continue to debug along these lines. |
|
I expand the debugging function: def show_log_handlers(id: str, expected_n_handlers: int):
import logging
from icecream import ic
root_logger = logging.getLogger("root")
ic(id)
if expected_n_handlers != len(root_logger.handlers):
ic(
root_logger.level,
root_logger.handlers,
root_logger.manager.loggerDict,
)
assert FalseAnd put the following at the top of the one test: def test_report_bare_res(request, tmp_path, test_context):
...
show_log_handlers("test_report_bare_res 0", 5)
from importlib import import_module
for name in (
"dotenv",
"fastapi",
"fsspec",
"hpack",
"httpcore",
"httpx",
"matplotlib",
"numba",
"pint",
"pycountry",
"requests",
"rich",
"sdmx",
"sqlalchemy",
"tqdm",
"urllib3",
"xarray",
"ixmp4",
"pyam",
):
import_module(name)
show_log_handlers(f"test_report_bare_res after `import {name}`", 5)Now I run with This indicates that the root logger's handlers are only wiped out by/as of the import of |
- Reduce number of jobs. - Reduce the set of tests run.
|
I don't know if I can find a solution for this today, but I just tried importing pyam before ixmp4, and it fails, too. So whatever it is that ixmp4 is doing, pyam seems to be guilty of the same. |
|
Both of them are configuring their logging via |
|
There's also a warning at the bottom of this section which might be relevant: if the root logger is modified during a test, the pytest.caplog handler may be removed, causing no logs to be captured. |
|
Both pyam and ixmp4 do something to the root logger which almost looks like clearing it: https://github.com/IAMconsortium/pyam/blob/main/pyam/logging.conf |
Keep in mind the issue we are seeing is not with Logger instances, but with Handler instances. The logging docs are, unfortunately, both verbose and also silent on a lot of points, including I think what happens to handlers.
This is the reason I wound up with code like this in message-ix-models: message-ix-models/message_ix_models/util/_logging.py Lines 256 to 258 in 4378be6 and To wit: message-ix-models looks for an instance of its own QueueHandler class, and if it is not there, adds it. It ignores other handlers (e.g. the Pytest ones), and does not remove or replace them. I tried but could not get this to work with I suspect by placing something like |
|
I've added the first version of show_log_handlers(0)
logging.config.fileConfig(logging_config, disable_existing_loggers=False)
show_log_handlers(1)And with that, I see: ic| id: 'test_report_bare_res after `import xarray`'
ic| id: 0
root_logger.level: 10
root_logger.handlers: [<QueueHandler (NOTSET)>,
<_LiveLoggingNullHandler (NOTSET)>,
<_FileHandler /dev/null (NOTSET)>,
<LogCaptureHandler (NOTSET)>,
<LogCaptureHandler (NOTSET)>]
ic| id: 1, root_logger.level: 0, root_logger.handlers: []
ic| id: 'test_report_bare_res after `import ixmp4`'
ic| root_logger.level: 0
root_logger.handlers: []
root_logger.manager.loggerDict: {'PIL': <Logger PIL (INFO)>,So it seems this function is indeed responsible for wiping out the handlers. |
|
According to their docs using |
|
I found a solution, the test is working fine again locally. We won't need to change anything if we can get the PRs I'm going to push to ixmp4 and pyam merged reasonably fast. Otherwise, we could use their branches. I'll push these tomorrow. |
- Reduce number of jobs. - Reduce the set of tests run.
|
I released a new version of ixmp4 that should include a fix, I don't yet know when pyam can follow suit. If we use their main-branch version, we should already be able to get a fix from them as well. |
|
Great! Could you please trial those adjustments on the #175 branch, when you have a chance? |
|
Not sure what's up with the coverage report, but the fixes work :) |
|
Glad to see that new pyam and ixmp4 releases have addressed this! In the future, on the off chance that message-ix-models users encounter issues with logging behaviour, we should keep in mind to check whether they are using the affected versions and remind them to upgrade. |
@glatterf42 noticed test failures such as these occurring on scheduled runs, starting today.
Symptoms:
caplogfixture fails to capture certain messages, so the test assertions that check for those messages end up failing.Actions to take:
The text was updated successfully, but these errors were encountered: