You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
create_app() reconfigures logging (logging.config.dictConfig, see flexmeasures/utils/config_utils.py), which replaces the handlers on the root logger. That removes the handler pytest's caplog fixture installed there. Every test that reads caplog afterwards in the same session sees an empty capture, so its log assertions fail — while the behaviour it is really testing is fine.
Which tests are affected therefore depends on the order tests happen to run in, so this surfaces as an intermittent failure rather than a consistent one.
test_app_queues_use_custom_global_and_queue_job_timeout builds a throwaway app from a config file, and is the only test that needs to do so; any other test that builds an app would have the same effect.
Why caplog.at_level is not a workaround
test_schema_mismatch_log_record_is_deduplicated already wraps its assertion in caplog.at_level(...) and still fails. at_level adjusts levels on the logger and the capture handler; it does not reinstate a handler that has been removed from the root logger. So the usual advice does not apply here, and reaching for it costs time before the real cause becomes visible.
Impact
Any test asserting on log output is order-dependent, and CI does not pin the ordering.
The failure points at the innocent test rather than at the one that reconfigured logging, so it reads as a bug in whatever code the failing test covers.
It bites new tests in particular: a log assertion can pass locally, in the file it was written in, and fail later once the suite is run in a different order.
Suggested direction
Contain the logging reconfiguration to the test that causes it, rather than fixing each affected test one at a time. Options worth weighing:
Have the test that builds an app restore the root logger's handlers afterwards (a fixture would make this reusable for any future test that builds one). Note that a naive save/restore of logging.getLogger().handlers around create_app() was not sufficient in a quick experiment, so the exact mechanism needs a closer look before settling on this.
Or stop create_app from calling dictConfig when running under pytest, so the test session owns its logging configuration.
Or, as a narrower fallback, have affected tests assert on the logger directly (e.g. patching current_app.logger.error) instead of on caplog. This is what PR Automations - first roundtrip for forecasts #2290 does for its own new test, but it treats the symptom rather than the cause.
Found while reviewing #2290, whose new test_invalid_cron_does_not_hide_other_due_automations was hit by this. That test has been made order-independent, so this issue is only about the underlying condition on main.
What happens
create_app()reconfigures logging (logging.config.dictConfig, seeflexmeasures/utils/config_utils.py), which replaces the handlers on the root logger. That removes the handler pytest'scaplogfixture installed there. Every test that readscaplogafterwards in the same session sees an empty capture, so its log assertions fail — while the behaviour it is really testing is fine.Which tests are affected therefore depends on the order tests happen to run in, so this surfaces as an intermittent failure rather than a consistent one.
Reproducing on
mainVerified on
187617742:test_app_queues_use_custom_global_and_queue_job_timeoutbuilds a throwaway app from a config file, and is the only test that needs to do so; any other test that builds an app would have the same effect.Why
caplog.at_levelis not a workaroundtest_schema_mismatch_log_record_is_deduplicatedalready wraps its assertion incaplog.at_level(...)and still fails.at_leveladjusts levels on the logger and the capture handler; it does not reinstate a handler that has been removed from the root logger. So the usual advice does not apply here, and reaching for it costs time before the real cause becomes visible.Impact
Suggested direction
Contain the logging reconfiguration to the test that causes it, rather than fixing each affected test one at a time. Options worth weighing:
logging.getLogger().handlersaroundcreate_app()was not sufficient in a quick experiment, so the exact mechanism needs a closer look before settling on this.create_appfrom callingdictConfigwhen running under pytest, so the test session owns its logging configuration.current_app.logger.error) instead of oncaplog. This is what PR Automations - first roundtrip for forecasts #2290 does for its own new test, but it treats the symptom rather than the cause.Found while reviewing #2290, whose new
test_invalid_cron_does_not_hide_other_due_automationswas hit by this. That test has been made order-independent, so this issue is only about the underlying condition onmain.