1

I have a function where I am doing some logging like so:

class Foo:
    def start(file):
        with open(file, 'r') as r:
            d = json.load(r)
        if "a" in d:
            log.debug("a in file")
        elif "b" in d:
            log.debug("b in file")

log is a logging object declared in the parent class of this function. When I use pytest to test the logging works correctly like so:

def test_logging_a(caplog):
    # open file that has "a" as key in dict
    file_a = # path to file a

    ff = Foo()
    with caplog.at_level(logging.DEBUG):
        ff.start(file_a)
    assert "a in file" in caplog.text


def test_logging_b(caplog):
    # open file that has "b" as key in dict
    file_b = # path to file b

    ff = Foo()
    with caplog.at_level(logging.DEBUG):
        ff.start(file_b)
    assert "b in file" in caplog.text

Both these tests pass. However, when I run pytest with logs in output pytest -s ... I get the log "b in file" twice. If I comment out the first test (or just comment out the call to start()) "b in file" is only logged once (as it should).

It seems like the tests are leaking. If I reverse the order of the test i.e. test_logging_b runs before test_logging_a, the same thing happens but in reverse, "a in file" is shown twice in console like it is running twice.

Why is this happening? I also tried to instantiate ff = Foo() once in a fixture but the same thing happened.

bcsta
  • 1,963
  • 3
  • 22
  • 61

1 Answers1

0

If handlers are being added to logger from inside the function that is being called multiple times, then that is the reason why this is happening. For example if StreamHandler(sys.stdout) is being added from a function that is called 5 times than logs will show up 5 times.

Handlers are not overridden but appended to. this should help.

bcsta
  • 1,963
  • 3
  • 22
  • 61