Bug Report
Description
In snakemake/api.py, the _cleanup() method calls cleanup_logfile() before stop():
def _cleanup(self):
if not self.output_settings.keep_logger:
logger_manager.cleanup_logfile() # closes handlers first
logger_manager.stop() # drains queue second
This ordering creates a race condition. cleanup_logfile() iterates logfile_handlers and calls handler.close() on all handlers where writes_to_file = True, which includes logger plugin handlers. At this point, the QueueListener background thread (set up in logging.py) is still running and may still be processing queued events.
The QueueListener._monitor() loop only catches queue.Empty, so if a handler's emit() raises after the handler has been closed (e.g., writing to a closed file), the background thread crashes and any remaining queued events are silently lost.
Affected Code Paths
snakemake/api.py:_cleanup() (~lines 170-174)
snakemake/logging.py:LoggerManager.cleanup_logfile() (~lines 693-698) — closes plugin handlers
snakemake/logging.py:LoggerManager.stop() (~lines 722-724) — drains QueueListener
How to Reproduce
This is a race condition, so it manifests as flaky behavior. We discovered it while developing a logger plugin (snakemake-logger-plugin-snakesee) that writes events to a JSONL file. Integration tests intermittently fail on Snakemake 9.14.0 because events are lost — the plugin's file writer is closed by cleanup_logfile() while the QueueListener thread still has events to process. The race window is small, making this a flaky test failure.
Any logger plugin that writes to a file (i.e., sets writes_to_file = True) is affected.
Expected Behavior
All queued log events should be fully processed and delivered to handlers before those handlers are closed.
Suggested Fix
Reverse the call order — drain the queue first, then close handlers:
def _cleanup(self):
if not self.output_settings.keep_logger:
logger_manager.stop() # drain queue first
logger_manager.cleanup_logfile() # then close handlers
Version Information
- Snakemake: 9.14.0
- Python: 3.12
- OS: macOS / Linux
Bug Report
Description
In
snakemake/api.py, the_cleanup()method callscleanup_logfile()beforestop():This ordering creates a race condition.
cleanup_logfile()iterateslogfile_handlersand callshandler.close()on all handlers wherewrites_to_file = True, which includes logger plugin handlers. At this point, theQueueListenerbackground thread (set up inlogging.py) is still running and may still be processing queued events.The
QueueListener._monitor()loop only catchesqueue.Empty, so if a handler'semit()raises after the handler has been closed (e.g., writing to a closed file), the background thread crashes and any remaining queued events are silently lost.Affected Code Paths
snakemake/api.py:_cleanup()(~lines 170-174)snakemake/logging.py:LoggerManager.cleanup_logfile()(~lines 693-698) — closes plugin handlerssnakemake/logging.py:LoggerManager.stop()(~lines 722-724) — drains QueueListenerHow to Reproduce
This is a race condition, so it manifests as flaky behavior. We discovered it while developing a logger plugin (snakemake-logger-plugin-snakesee) that writes events to a JSONL file. Integration tests intermittently fail on Snakemake 9.14.0 because events are lost — the plugin's file writer is closed by
cleanup_logfile()while the QueueListener thread still has events to process. The race window is small, making this a flaky test failure.Any logger plugin that writes to a file (i.e., sets
writes_to_file = True) is affected.Expected Behavior
All queued log events should be fully processed and delivered to handlers before those handlers are closed.
Suggested Fix
Reverse the call order — drain the queue first, then close handlers:
Version Information