Test that has child process logging to stdout not consistent when run with python -m unittest vs nose2

[mikeholler]

I have a command line command that I'm trying to write an end-to-end test for to make sure everything is working well. I wanted to invoke the CLI via a multiprocessing.Process, because when the CLI starts running it configures the root logger, and I want to test that, along with everything else, without creating inconsistencies in my test suite. Below is a simple of the type of test I'm interested in doing. You can see that I have child, which is the entrypoint of my CLI, you can see that it configures logging, and also that it makes a couple of print statements. The test itself verifies both the print statement and the log message show up in stdout, which is redirected to a file in a child process.

When I run this test with unittests, everything passes. When I run with nose2, I get a failure. See below for details.

tests/test_example.py

import logging
import sys
import tempfile
import unittest

from pathlib import Path
from multiprocessing import Process


def child():
    logging.basicConfig(
        handlers=[logging.StreamHandler(sys.stdout)],
        level=logging.INFO,
        format="%(message)s",
        datefmt="%Y-%m-%dT%H:%M:%S%z",
    )

    print("MY PRINT STATEMENT")
    logging.info("MY LOG MESSAGE")


def child_wrapper(target, stdout_file, stderr_file):
    sys.stdout = stdout_file.open("w")
    sys.stderr = stderr_file.open("w")

    try:
        target()
    finally:
        sys.stdout.flush()
        sys.stderr.flush()


class TestLoggingInChildProc(unittest.TestCase):
    def test_logging_in_child_proc(self):
        with tempfile.TemporaryDirectory() as d:
            stdout_file = Path(f"{d}/stdout.txt")
            stderr_file = Path(f"{d}/stderr.txt")

            p = Process(
                target=child_wrapper,
                args=[child, stdout_file, stderr_file],
            )
            p.start()
            p.join()
            p.close()

            self.assertEqual(
                "MY PRINT STATEMENT\nMY LOG MESSAGE",
                stdout_file.read_text().strip()
            )

            self.assertEqual("", stderr_file.read_text().strip())

When I run tree ., I see:

.
└── tests
    ├── __init__.py
    └── test_example.py

1 directory, 2 files

When I run python -m unittest tests.test_example the test passes, but when I run nose2 test_example the test fails. Here is the failure text:

F
======================================================================
FAIL: test_logging_in_child_proc (tests.test_example.TestLoggingInChildProc)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/tests/test_example.py", line 47, in test_logging_in_child_proc
    self.assertEqual(
AssertionError: 'MY PRINT STATEMENT\nMY LOG MESSAGE' != 'MY PRINT STATEMENT'
- MY PRINT STATEMENT
?                   -
+ MY PRINT STATEMENT- MY LOG MESSAGE

----------------------------------------------------------------------
Ran 1 test in 0.004s

FAILED (failures=1)

When I invoke this test using python -m unittest test_example.py the test passes. However, when I invoke this script using nose2

[sirosen]

Thanks for reporting this and providing a reproduction of the issue; I can confirm that this isn't behaving correctly under nose2 and I've produced a smaller reproduction to try to narrow this down more. We don't need the indirection/wrapper to get this to fail, this also doesn't work:

import logging
import os
import sys
import unittest
from multiprocessing import Process


def child(stdout_file):
    old_stdout = sys.stdout

    with open(stdout_file, "w") as fp:
        try:
            sys.stdout = fp
            logging.basicConfig(
                handlers=[logging.StreamHandler(sys.stdout)],
                level=logging.INFO,
                format="%(message)s",
                datefmt="%Y-%m-%dT%H:%M:%S%z",
            )
            logging.info("MY LOG MESSAGE")
        finally:
            sys.stdout = old_stdout


class TestLoggingInChildProc(unittest.TestCase):
    def test_logging_in_child_proc(self):
        stdout = os.path.join(os.path.dirname(__file__), "stdout.txt")

        p = Process(target=child, args=[stdout])
        p.start()
        p.join()
        p.close()

        with open(stdout) as fp:
            self.assertEqual("MY LOG MESSAGE", fp.read().strip())

I also couldn't find a plugin responsible for the failure. e.g. This fails: nose2 --exclude-plugin nose2.plugin.logcapture test_stdio

I'll look into this as I'm able, but there's no very obvious place I can point at as the cause.

Given that this doesn't work even on very old nose2 versions (dating all the way back to 0.3.0), I'm not confident that this will be quick and easy by any means. I'm marking this as "help wanted". If anyone has insights -- perhaps something special in unittest which we need to backport into nose2 -- it would be a tremendous help.