skip to content

Why does logging.handlers.RotatingFileHandler lose records when eight ETL worker processes share one log file?

level: seniorimportance: should knowfreq 35%

answer

  1. Eight writers, one file, one policy each
  2. The handler's lock never leaves the process
  3. An open file follows the inode, not the name
  4. Rollover does not just rename, it deletes
  5. Every fix is a way of having one writer

basics

~20 s

Each process holds its own file object and rotates independently. When one renames the live file, the others keep appending through their open descriptors into the renamed file, which a later rollover deletes. Route every process to one writer.

solid answer

~50 s

The handler's lock is a `threading.Lock`; it coordinates threads inside one process and means nothing across processes. When worker A's `doRollover()` renames `etl.log` to `etl.log.1`, workers B through H are still holding open descriptors on that inode, so their records land in `etl.log.1` — and when the next rollover shifts `.1` to `.2` past `backupCount`, those records are deleted. Worse, two processes can rotate within milliseconds of each other and each shift the other's backups, so the numbered files no longer form a sequence. The fixes are all forms of *one writer*: give each process its own filename containing `os.getpid()`; or attach a `logging.handlers.QueueHandler` over a `multiprocessing.Queue` in the workers and run one `QueueListener` holding the rotating handler in the parent; or stop rotating in-process, use `WatchedFileHandler`, and let an external rotation tool own the file.

code

python · 18 lines
python
import logging
import logging.handlers
import os
import tempfile

log_dir = tempfile.mkdtemp()
path = os.path.join(log_dir, f"etl-export.{os.getpid()}.log")
handler = logging.handlers.RotatingFileHandler(
    path, maxBytes=1_000_000, backupCount=3, encoding="utf-8"
)

logger = logging.getLogger("etl.worker")
logger.setLevel(logging.INFO)
logger.addHandler(handler)
logger.info("worker %d exported batch %d", os.getpid(), 7)
handler.close()

print(os.path.basename(path))

go deeper

for a junior

Recall the headline rule: one rotating file handler per file, and never several processes rotating the same file. Knowing that the handler's lock protects threads only is enough at this level.

for a middle

Explain the mechanism end to end: independent file objects, a rename the other processes never see, and a later rollover deleting the file they are still writing into. Name at least one correct fix.

for a senior

Diagnose it from symptoms and choose between the fixes with their costs: per-process files, a single writer fed by a queue, a network collector, or external rotation. Have a configuration-only mitigation ready for before the real fix ships.

for a principal

Own the logging topology for a fleet of multi-process services: where the single writer lives, what happens when it dies, and whether files on hosts are the right destination at all versus a collector the platform runs.

### The scenario A nightly export job fans out into eight worker processes, each writing progress lines for the batches it pushes to the warehouse, all configured with the same `logging.handlers.RotatingFileHandler` on one file. The job is idempotent-ish: a failed batch is retried, and the log is the only record of whether a given batch's warehouse write happened once or twice. After the file first crosses `maxBytes`, lines start disappearing — and the ones that survive cannot settle the duplicate question, because the segment that would have shown the retry is gone. ### Why it happens `RotatingFileHandler` was designed for one process. Three properties make it unsafe when several share a file: 1. **The lock is process-local.** Every `logging.Handler` serialises `emit()` with a `threading.Lock`. That makes threads inside one interpreter safe. Another process has its own handler object, its own lock, and no knowledge of yours. 2. **Each process holds an independent file object.** On Unix an open file refers to an inode, not to a name. When worker A performs the rename inside `doRollover()`, workers B–H do not notice: they keep appending to the same inode, which is now called `etl.log.1`. 3. **Rollover deletes.** `doRollover()` shifts `etl.log.1` to `etl.log.2` and so on, deleting whatever falls past `backupCount`. The other workers' records are inside those shifting files, so they are destroyed on a later rollover — the "lost lines" symptom. Add the interleaving of eight independent rollovers and the numbered files stop being a sequence at all: two processes can each rename the base file within the same millisecond, and each can remove a backup the other just created. On Windows the picture differs but is no better — the rename of an open file fails outright, so rollover raises and the record goes to the handler's error path. ### What is *not* the problem Interleaving of individual lines usually is not the damage. A handler formats a record and issues a single write of the whole line to a file opened in append mode, and on Unix that is well behaved enough in practice that mixed-up half-lines are rare. Candidates who reach for "the lines get scrambled" are describing a cosmetic worry while missing the destructive one: rotation deletes other writers' data. ### The fixes, in order of how much they cost **One file per process.** Put `os.getpid()` in the filename. Each process rotates a file only it owns, so no race exists. It costs you a single tailable stream and leaves a directory of files to aggregate, but it is a configuration-only change and it is correct immediately. **One writer, fed by a queue.** Each worker attaches a `logging.handlers.QueueHandler` over a `multiprocessing.Queue`; the parent process runs a `logging.handlers.QueueListener` that owns the single rotating handler. `QueueHandler.prepare()` merges the message with its arguments and clears the fields that would not pickle, so records survive the trip between processes. This is the standard answer, keeps one ordered file, and moves the disk write off the workers. **A network collector.** `logging.handlers.SocketHandler` or `logging.handlers.SysLogHandler` sends every record to one receiver that owns the file. Same shape as the queue answer, with the receiver outside the process tree, and it is what you want once the workers are on different machines. **Stop rotating in-process.** Set the handler to a `logging.handlers.WatchedFileHandler` and let a scheduled rotation tool on the host rename the file; every process notices and reopens. No process ever renames, so the destructive step is gone. ### The change you can make today When the structural fix has to wait for the next three-week release train, the mitigations that need no code path change are the first and the last: switch the workers to per-process filenames, or turn off in-process rotation and hand the file to an external rotator. Both are configuration, both remove the delete step, and both preserve the evidence you need for the duplicate-write question. ### Recognising it in the wild Symptoms that identify this specific failure: a rotated file noticeably smaller than `maxBytes`; a monotonic counter in the log with gaps that fall exactly at rollover boundaries; timestamps that jump backwards when you concatenate the numbered files in order; and error output on stderr from the handler's error path on the platform where the rename fails.

  • Does adding a threading.Lock around the logging calls fix this?
    No. A `threading.Lock` exists inside one interpreter's memory; a separate process has its own object and never sees yours. Only something the operating system arbitrates — a file lock, a single writer process, or a socket receiver — can coordinate across processes, and the handler does not take one. Reaching for a thread lock here is the classic wrong answer.
  • Do the log lines themselves get scrambled when eight processes append to one file?
    Rarely, and that is not the damage. Each record is formatted and written as one write to a file opened in append mode, which on Unix behaves well enough that torn lines are uncommon at ordinary line lengths. The destructive part is rollover: renaming and deleting files that other processes are actively writing into.
  • The structural fix ships on the next three-week release train. What goes in today?
    A configuration-only mitigation that removes the delete step. Either give each worker its own filename containing its process id, so no process ever renames a file another is writing, or set `maxBytes` aside entirely, switch to `logging.handlers.WatchedFileHandler`, and let the host's rotation tool own the file. Both preserve the records you need while the queue-based rewrite is built.

saying these in an interview costs you the question

  • Claims append-mode writes make rotation safe
  • Adds a threading.Lock to fix a cross-process race
  • Thinks delay=True or a bigger maxBytes avoids it
  • Assumes the operating system serialises the rename for all writers
  • Only worries about interleaved lines, not deleted files
  • Opens the shared file in write mode in each process

context

resolving links…