BUG/TST: Sporadic logging output gets dumped after session close

[tangkong]

Current Behavior

If I run the entire test suite locally, at the end I get a bunch of failed logging calls from spawned workers, despite the session exiting successfully

====================================================================================== 85 passed, 1 warning in 13.31s ======================================================================================
--- Logging error ---
Traceback (most recent call last):
  File "/cds/group/pcds/pyps/conda/py39/envs/pcds-5.8.4/lib/python3.9/logging/__init__.py", line 1086, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/cds/home/r/roberttk/devrepos/BEAMS/beams/sequencer/helpers/Worker.py", line 45, in stop_work
    logger.info("Calling stop work on")
Message: 'Calling stop work on'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/cds/group/pcds/pyps/conda/py39/envs/pcds-5.8.4/lib/python3.9/logging/__init__.py", line 1086, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/cds/home/r/roberttk/devrepos/BEAMS/beams/sequencer/helpers/Worker.py", line 59, in stop_work
    logger.debug("Worker process joined")
Message: 'Worker process joined'
Arguments: ()
(pcds-5.9.1+beams)roberttk@psbuild-rhel7-01:~/devrepos/BEAMS(enh_pytrees_behaviors -)$ echo $?
0

Expected Behavior

We shouldn't spam the console if possible.

Context / environment

I've tried various things to remedy this, which have possibly narrowed the space of possible solutions. I also encountered this in the past and thought I fixed it...

This logging dump seems to only happen when the entire test suite is run altogether, and adding the -s flag seems to prevent this specific type of console dump (though there are still logging messages after session close). Running individual files does not reproduce this (with or without the -s option)

The prime suspect might be the central_logging_setup fixture, which is meant to set up the beams central logging. This is currently an auto-use fixture, which runs before every test. Switching the fixture from autouse=True to scope="session" does not affect this behaviour either.

Summary of debugging thus far:

• pytest -> Worker Logging dump
• pytest -s -> different logging messages, no error
• Switching central_logging_setup fixture (autouse=True <> scope="session") -> no effect

This seems to be caused when the worker threads try to print to the console (we do not configure file-based logging in the test suite). A possible explanation is that pytest re-directs the console stream when we don't include the -s flag, but closes it very promptly, and worker processes error. In contrast, if we add -s, pytest leaves that console stream as the normal stdout, and it does not get closed.

Steps to Reproduce (for bugs)

1. pytest
2. console vomit

Suggested Solution

Maybe keep track of worker threads that are started, and make sure they're closed before moving on? I don't want to get into the weeds of re-routing things that pytest is rerouting