Skip to content

Build1 publisher3 min readPublished

Forking mid-emit hands a worker a logging lock that stays taken

Python's logging module keeps an RLock behind every handler. One shared setup_logging() therefore deadlocks a forked pool on one machine and silently drops worker records on another, and a single-OS review only ever sees one of them.

The Engineer · Build desk

Illustration accompanying Forking mid-emit hands a worker a logging lock that stays taken

What happened

  • Python's stdlib logging wraps every handler in an RLock, and a fork that happens while a parent thread holds that lock inside emit() hands the child a lock nobody in it will release.
  • The forked worker's next logging.info() call then blocks forever, and the pool join sits waiting on that worker.
  • Under spawn the child inherits neither the lock nor the handlers, because it starts a fresh interpreter in which the parent's import-time basicConfig() never ran.
  • Worker logs from a spawned child vanish, and the run looks fine from outside because the parent process still prints its summary.
  • The post's recommended shape puts a QueueListener and the real handler in the parent and gives workers a QueueHandler only.

Compiled by The EngineerSomething wrong?How this is made

Why it matters

  • constraint A review conducted on one operating system can only observe one of the two failures, so the diff either passes on macOS spawn and hangs Linux CI, or passes on Linux fork and goes quiet for Windows users.
  • decision Merging duplicated logging setup into one shared helper becomes a decision about start method, since the CLI and the worker need different handler sets on the same import.
  • exposure The spawn failure is quiet: the parent's summary stands in for records that were never written, so the gap surfaces only when somebody goes looking for a specific log line.
  • cost Adopting the queue pattern means owning the listener's lifecycle, and the post hands the adopter both the JSON-versus-text choice and the SIGTERM shutdown path.

The lock is per handler, and it is held for the whole of `emit()` [1][2]. Timing decides which of the two failures you get. In the lab file the handler sleeps 0.4 seconds inside `with self.lock` before it prints [13]. The parent starts a thread that emits, waits 0.05 seconds, then creates the child [14]. So the fork lands with roughly 0.35 seconds of the hold still to run [23]. In the parent, the sleeping thread wakes and releases. In the child there is no such thread, and the copied lock stays taken [2].

The join timeout in the lab is 3.0 seconds [15], seven and a half times the handler's own hold [24]. A child merely queued behind a busy lock clears well inside that. A child still alive when the timeout expires is waiting on a lock held by a thread that stayed behind in the parent. On interpreters that still offer `fork`, the post reports, the child often never finishes [16].

Under spawn the same worker function answers a different question. It collects the class names of the root logger's handlers, and returns the string `NO_ROOT_HANDLERS` when the list is empty [17]. The list is empty because the parent's import-time `basicConfig()` ran in a different interpreter [4]. Nothing goes through the parent's handler, the child usually finishes [16], and the parent still prints its summary [5].

The change that sets this up is dull. Someone moves `logging.basicConfig(...)` into a helpers module, so every worker import configures the root logger, or the parent configures it before the pool starts and children inherit whatever was there [8]. One shared `logutil.py` imported by the CLI and by the worker is enough [9]. The dev.to post's author puts the review dynamic this way: "A free coding model will still offer you one setup_logging() import and call it tidy." [10] The author calls that dedup the wrong merge [9], and describes handlers as "file descriptors with opinions" [11].

The suggested shape after that is the stdlib queue [20]: after either start method, a worker must not keep a StreamHandler pointing at the same stdout lock the parent uses [21]. The post labels its queue snippet a proposed pattern, unexecuted in production, and leaves two things to the adopter: JSON versus text, and closing the listener on the path that handles SIGTERM [22].

What is on the page is a lab, not a measurement. The post calls the file sample code and not a production collector [19], and it gives the outcomes as "often" and "usually" with no counts [16]. The lab also widens the window on purpose: for the fork hang to appear in your pool at the rate it appears there, your handlers would have to hold their locks for something close to the 0.4 seconds the sample sleeps [13][12]. The ordering is what transfers. A parent thread inside `emit()` at the moment a child is created is a state your code either can reach or cannot, and the `fork` branch of `mp.get_all_start_methods()` is where you find out [18].

What to watch

  • Whether the author publishes the full queue-logging module, including the listener close on the SIGTERM path the post leaves undecided.
  • A CI job that runs the lab under every start method the interpreter offers and records alive and exitcode per method, turning "often" into a rate.
  • Whether coding assistants that propose one shared setup_logging() begin treating CLI entry points and worker modules as different callers.
Loading claim ledger
Loading source directory links
Loading share composer
Loading topic controls
Loading related stories