Skip to content

Building an app in a test silently breaks pytest's caplog for every test after it #2455

Description

@Flix6x

What happens

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.

Reproducing on main

Verified on 187617742:

$ pytest "flexmeasures/utils/tests/test_job_utils.py::test_app_queues_use_custom_global_and_queue_job_timeout" \
         flexmeasures/data/tests/test_utils.py -q -p no:randomly
FAILED flexmeasures/data/tests/test_utils.py::test_schema_mismatch_log_record_is_deduplicated
1 failed, 8 passed

$ pytest flexmeasures/data/tests/test_utils.py -q -p no:randomly
8 passed

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.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions