Repository navigation
Fix Python 3.13 "Listener already started" in multiprocessing log listener - #90
Merged
Merged
Conversation
beamcon_3D.smooth_fits_cube and beamcon_2D.smooth_fits_files started the shared module-level log listener on entry but only called enqueue_sentinel() on exit, never stop(). That leaves QueueListener._thread set even after the monitor thread has exited, and every exit path (dry-run return, early raises) skipped the sentinel entirely, leaving the monitor thread running. Python 3.13's QueueListener.start() refuses to start when _thread is not None, so a second call in the same process raises "Listener already started"; 3.11/3.12 tolerate the stale state. Add a running_log_listener() context manager that starts the listener and guarantees stop() runs in a finally block, then use it to wrap both functions' bodies so every exit path leaves the listener fully stopped. This unblocks running racs-tools under Python 3.13 (e.g. flint's flint_convol, which calls smooth_fits_cube more than once per process).
Review of the previous commit turned up two real defects: Guarding stop() with a reentrancy count. Because stop() joins the monitor thread (enqueue_sentinel() did not), nesting two running_log_listener blocks hung forever: the inner stop() enqueued a sentinel that the outer block's monitor consumed, so the inner join() never returned. Two concurrent callers hit the same shape, and the reverse interleaving raised AttributeError from self._thread.join() on <=3.12, which has no None guard. The listener is a process-wide singleton, so nested and concurrent blocks now share one run: the first to enter starts it, the last to leave stops it. Keeping one queue handler per process. init_worker added a QueueHandler unconditionally, so with a thread executor - the default - handlers stacked up one per worker and stayed attached (1 -> 3 -> 5 -> 7 over three calls). That fanned each record out once per handler, and since the listener is no longer left running between calls, those handlers kept filling the queue with nothing consuming it: 6 copies of a single record for a logger left in that state. Pre-existing, but only harmless while a listener ran forever. Also adds 3.13 to the CI matrix, so the interpreter this series targets is actually exercised, and regression tests for both defects (all three fail against the previous commit).
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
RuntimeError: Listener already startedraised on the second call tobeamcon_3D.smooth_fits_cube(orbeamcon_2D.smooth_fits_files) within the same process.racs_tools/logging.pybuilds a single module-levelQueueListenerat import time. Both functions calledlog_listener.start()on entry but only calledenqueue_sentinel()on exit (neverstop()), and every early-return/raise path (dry-run return, validation errors, "no files found") skipped even that. This leftQueueListener._threadset after the monitor thread had already exited. Python 3.11/3.12 tolerate restarting in that state; Python 3.13'sQueueListener.start()raises if_thread is not None.running_log_listener()context manager inracs_tools/logging.pythat starts the listener and guaranteesstop()runs in afinallyblock, then wraps the bodies ofsmooth_fits_cubeandsmooth_fits_filesin it, removing the bareenqueue_sentinel()calls (calling bothenqueue_sentinel()andstop()would double-sentinel the queue and silently break future runs — the fix removes the former sostop()'s own sentinel is the only one consumed).flint'sflint_convol --mode convol --cubes, which callssmooth_fits_cubemore than once per process (a dry-runget_cube_common_beamfollowed byconvolve_cubes), and any long-lived worker (dask, celery) that outlives the task it ran.Follow-up (not in this PR)
The listener is still a process-wide singleton, so two concurrent
smooth_*calls in the same process would still interfere with each other. A fresh(logger, listener, queue)triple per call, with the queue passed explicitly intoinit_worker, would remove that class of bug entirely, but is a larger change than this fix warrants.Test plan
tests/test_logging.py:test_smooth_fits_cube_twice: two dry runs ofsmooth_fits_cubein one process both succeed.test_smooth_fits_cube_dryrun_then_real: a dry run followed by a real convolution (the orderflint's CLI uses).test_smooth_fits_cube_exception_then_success: an exception path (no files found) followed by a successful call.test_running_log_listener_relays_records_across_calls: drivesrunning_log_listenerdirectly across repeated start/stop cycles and asserts worker log records still reach the handler each time (a stale sentinel from the old bug would silently break this).log_listener._thread is Noneand the queue is empty after every call.guard_queue_listener_startfixture monkeypatchesQueueListener.startto install Python 3.13's own guard, so these tests are meaningful (not a no-op) when run under 3.11/3.12.ruff check/ruff format --checkpass on the changed files.RuntimeErroragainst the pre-fix code using the same guard, to confirm the regression tests actually exercise the bug.test_2d.py/test_3d.py) end-to-end in this environment since MIRIAD (fits/convolbinaries) isn't installed here; those failures are pre-existing environment gaps unrelated to this change.Generated by Claude Code