Dvc: Investigate flaky logger tests

[pared]

Sometimes, upon running parallel tests, test_logger fails.
Chance for failing seems to increase upon running
python -m tests -n={X}
where X > num_cpu
and inserting sleep for 1 second before assertion in one of the test_logger.py tests.

Running with X < num_cpu seems to decrease chance of failing

self = <tests.unit.test_logger.TestColorFormatter object at 0x7efcf95d3c88>, caplog = <_pytest.logging.LogCaptureFixture object at 0x7efcf95f0908>

    def test_exception(self, caplog):
        try:
            raise ValueError
        except Exception:
            logger.exception("message")

        expected = (
            "{red}ERROR{nc}: message\n"
            "\n"
            "{footer}".format(footer=formatter.footer, **colors)
        )

        with caplog.at_level(logging.INFO, logger="dvc"):
>           assert expected == formatter.format(caplog.records[0])
E           IndexError: list index out of range

tests/unit/test_logger.py:70: IndexError

[pared]

might be usefult to reproduce:

#! /bin/bash
for i in {1..10}
do
  python -m tests -n=24 >> test_result.log
done

[ghost]

@pared , this is interesting, caplog is missing to capture some logs, but it only happens on the test_logger.py :thinking: , also, what's up with the sleep(1), how did you discover that?

By the way, I was able to reproduce this.

[pared]

To be honest I just had suspicion that we have some kind race condition and assumed that there will be higher chance of "test overlapping" if one is too slow. Tried it and it seems to work.

[ghost]

Relevant: https://docs.pytest.org/en/latest/flaky.html

[efiop]

Fixed by #1875