I Blamed the Silent Worker for 48 Hours. The Logging Lock Survived fork()

Have you ever watched a child process sit in ps, healthy-looking, and still refuse to emit one log line? I spent forty-eight hours in that exact hole, and I blamed the process supervisor before anything else. The parent printed startup banners just fine, health checks returned 200, and the child consumed no CPU. So why would a process that clearly started go completely mute the moment real work began?

The mute worker is a logging story, not a crash story

I wanted a crash, a traceback, a nonzero exit code, or any other honest signal of failure. Instead I got a child that stayed runnable, answered nothing useful, and left strace parked on a futex wait. Does that pattern sound like a network bug to you, the way silent workers usually point at connection pools? The parent used multiprocessing.Process, a module-level logger, and background threads that touched logging during startup.

That last detail is the entire incident, and I simply refused to believe it until the second day. Threads plus fork is a documented hazard in CPython, not some mysterious runtime curse. I had read that warning before, and I still did not print the start method. Why do we skip the one diagnostic line that would have ended the whole hunt?

Field notes, hours 0–8: I chased the wrong process

I restarted the parent, added flush=True, redirected to a file, and even wrapped the process in stdbuf -oL. None of those tricks moved a single extra byte of log output out of the child. Then I attached strace -p and stared at FUTEX_WAIT, which is a rotten thing to see when you expected write. The disk was not full, stdout was not a dead pipe, and /proc/<pid>/fd still showed the log file open.

The process would not return from the logger, and I kept treating that as an I/O problem. Silent-but-alive is a lock story until the syscall log says otherwise. I did not believe that yet, so I kept polishing handlers in the parent. That wasted the morning without producing one child line.

What I tried, in order:

1. Restart the parent and watch ps for a freshly forked child pid.
2. Force line buffering with PYTHONUNBUFFERED=1 and stdbuf -oL.
3. Point the handler at an absolute file path instead of stdout.
4. Dump /proc/<pid>/fd and confirm the log file was really open.
5. Run strace -p on the child and freeze on futex.

What broke was simple: every "make logging louder" change ran in the parent, or ran before fork. Louder parent logs never proved the child could log. They only made me feel busy while the child stayed parked on the same futex.

Field notes, hours 8–24: I made it worse with more logging

Naturally I sprinkled extra logger.info calls around the child target function, which is the wrong medicine for a lock you cannot see. Have you noticed how debugging a deadlock often adds more lock traffic to the same path? I did that for a full workday, and the extra calls made the race easier to lose. I also flipped log levels, installed a StreamHandler twice, and created the classic duplicate-handler mess in the parent process.

The child stayed silent. The parent started shouting every line twice, which felt like progress and was not. Duplicate parent logs are a configuration smell, not evidence that the child logger is alive. I still had not printed the start method, which is the embarrassing part of this notebook.

Commands I actually ran:

python3 -c "import multiprocessing as mp; print(mp.get_start_method(allow_none=True))"
ps -o pid,ppid,stat,wchan,cmd -p "$CHILD"
strace -p "$CHILD" -s 200

wchan said futex_wait_queue_me, and that is not a networking word no matter how hard you squint. Why did I still keep blaming sockets and supervisors for another afternoon? Because a mute worker in my muscle memory belongs to pools, not to the stdlib logger.

Field notes, hours 24–40: The lock was already held

Here is the shape of the failure, and it looks embarrassingly small once you draw the arrows. I wish I had drawn them on hour three instead of hour thirty.

• The logging module keeps a module-level lock around handler I/O and formatting.
• Threads in the parent may hold that lock while they emit a record.
• fork() copies the lock into the child in whatever state it currently has.
• The thread that owned the lock does not exist in the child address space.
• The next logger.info in the child waits forever for a release that cannot happen.

Would spawn have saved me from this class of hang? Yes, because spawn starts a fresh interpreter and does not copy a held lock. Would forkserver have saved me in the common case? Usually yes, since the server process is not your busy parent. I was on fork, and I had not printed the start method until hour thirty, which is late.

Do not guess the start method from the platform name, the container image, or last year's blog post. Print it in both processes, because laptop defaults and worker defaults drift without asking you. I also checked a nasty cousin of this bug: a handler whose underlying stream was stuck in a partial write. That was not my hang, but it is worth a look if strace shows write instead of futex. Different syscall, different forty-eight hours.

Hours 40–48: A reproducer that actually fails

I stopped poking production-shaped code and wrote a script that is allowed to fail in the open. If this hangs on the CHILD line, you have the inherited lock. If it prints both lines, your start method or your timing did not copy a held lock, so loop it. Label this as a race: one run is not a proof, and ten clean runs on spawn prove nothing about fork.

"""Reproducer: a held logging lock plus fork() mutes the child.

Label: run this yourself. The race is timing-dependent, so loop a few times.
"""
import logging
import multiprocessing as mp
import threading
import time

logging.basicConfig(level=logging.INFO, format="%(processName)s %(message)s")
log = logging.getLogger("repro")


def chatter():
    while True:
        log.info("parent-thread chatter")
        time.sleep(0.001)


def child_main():
    log.info("CHILD reached target")  # may never print under fork


if __name__ == "__main__":
    mp.set_start_method("fork")  # force the dangerous path on Unix
    t = threading.Thread(target=chatter, daemon=True)
    t.start()
    time.sleep(0.05)
    p = mp.Process(target=child_main, name="Child")
    p.start()
    p.join(timeout=5)
    if p.is_alive():
        print("child hung; logging lock likely inherited held")
        p.terminate()
    else:
        print("child exited; try again, the race is not every run")

Run it like this:

python3 repro_fork_logging.py

If you cannot force fork on your laptop, that result is already a finding you should write down. A machine that refuses fork will hide this bug until the first Linux worker image hits a threaded parent. Ask yourself: are you debugging the worker, or debugging your laptop's start method? I spent a day debugging the laptop.

What I would run tomorrow morning

A short checklist beat another day of guessing around the orchestrator. I would run these steps before I touch log shippers, sidecars, or worker replica counts again.

1. Print multiprocessing.get_start_method() in the parent and again in the child.
2. Print threading.enumerate() in the parent right before you create the process.
3. In the child, as the first line, write to a raw fd with os.write(2, b"child-alive\n").
4. Only then call logging. If the raw write appears and the log does not, it is the lock.
5. Prefer QueueHandler plus a QueueListener in the parent, or switch the start method to spawn.
6. If you must stay on fork, register os.register_at_fork hooks that reinitialize logging.

Minimal child canary:

import os
import logging

def child_main():
    os.write(2, b"child-alive\n")
    logging.getLogger("repro").info("child-log")

The canary splits "process started" from "logger is usable", which is the distinction I needed on day one and did not have. If stderr shows child-alive and the log file stays empty, stop tuning formatters. You are staring at a lock that nobody in the child can release.

A small decision table

Keep the table next to the canary. It stops you from mixing five bugs into one incident report. I mixed at least three before hour twenty-four, and that is why the notes look this messy.

Where a second Linux interpreter actually helped

My laptop would not reproduce the hang, because it would not take fork the way the worker image did. I needed a throwaway Unix machine that could run the script above without mixing desktop start-method defaults into the evidence. That is an environment problem, not a clever-prompt problem.

Disclosure: This article was prepared as part of MonkeyCode's product outreach. I used MonkeyCode's free model access to sketch the first version of that reproducer, and the free server option to run it on a clean Linux interpreter I did not have locally. The draft mixed fork and spawn in one file until I forced the start method inside main. The server was a second environment, not a production host, and not proof that a model understands lock inheritance.

If you already have two Unix boxes with different start methods, you do not need that detour at all. If you do not, a free server is one way to print a second get_start_method() without spending the day on VM images.

Limitations, and who should skip this

This write-up is a fork-plus-logging checklist, not a general multiprocessing tutorial you can paste into every service. QueueHandler introduces a queue, a listener thread, and the chance of dropped records when the queue fills under bursty logging. spawn avoids the inherited lock, and it also avoids inherited sockets, file descriptors, and RNG state, which is usually what you wanted. os.register_at_fork is Unix-only, easy to forget in a library, and easy to register too late.

Please skip this approach if any of the following is already true for you:

• You already run spawn or forkserver everywhere, including CI workers.
• You are on Windows, where fork is not available and this race does not copy that way.
• You want to keep fork for copy-on-write savings and you refuse to change logging.
• You plan to point real traffic at a free scratch server, which is the wrong job for it.
• Your mute child is stuck in recv or epoll, not futex — that is a different incident.

I still would not use a coding model as the source of truth for lock semantics in CPython. Ask it for a reproducer skeleton, then run the skeleton until it hangs or it clearly does not. The useful part is a second interpreter with a different start method, not a confident paragraph about futexes.

What I would repeat

I would print the start method before I blame the orchestrator, the image, or the log shipper. I would put a raw os.write canary in the child before I add more logger.info calls. I would treat "silent but alive" as a lock until strace names a different syscall. And I would stop adding handlers in the parent while I am still trying to prove the child can log.

Would I still waste the first eight hours on buffering flags and stdbuf? Probably yes, because buffering bugs are common and this inherited lock is not. The difference is I now leave that path once wchan says futex. That is the whole lesson I kept from the two days, and it is the one I would repeat.