Python logging Tested: 6 Real Errors and Lost Records

PythonloggingTroubleshooting

I actually ran all six configurations below on Windows 11 with Python 3.13.14, and every line count in this article came from counting the files afterwards, not from estimation. What started it was specific: a service behind Gunicorn where the INFO lines before a crash were on disk but the DEBUG line at the moment of the crash was not. The file was rotating, the disk was not full. The cause turned out to be two unrelated things stacked on each other — rotation keeps only three files, and six worker processes were overwriting one another.

No affiliate links in this article. There is nothing to buy here. Every number below comes either from a run on this machine or from the official documentation, quoted.

Scope: interpreter is Python 3.13.14 (MSC v.1944 64 bit, AMD64); the logging module file lives at ...\python\versions\3.13.12\Lib\logging\__init__.py. Official sources are docs.python.org's Logging HOWTO and Logging Cookbook (accessed 2026-10-23; the page header shows 3.15.1). Each check below gives two sources: the official wording, plus either a literal from the source on this machine or a measured number. Where the two disagree, I say so.

Six configurations: 1800 lines in, how many on disk

All six use the same %(message)s format and the same 40-byte padding. Only the concurrency shape and the handler type change.

Setup	Lines written	Lines readable on disk
Single process, FileHandler (no rotation)	1800	1800
Single process, RotatingFileHandler(4096, 2)	1800	180
Single process, 6 threads sharing one RotatingFileHandler	1800	183
6 subprocesses, each its own FileHandler (no rotation)	1800	1674 (7.00% fewer)
6 subprocesses, each its own RotatingFileHandler	1800	220 and 200 (two runs)

The first row is the baseline: one process, no rotation, nothing lost. The second row is the same code with only the handler type changed, leaving 180 lines. That is not a bug, it is exactly what backupCount=2 with maxBytes=4096 means — three files of roughly 4 KB, forever. Rows four and five are the ones to worry about: once processes are involved, even a plain FileHandler that never rotates loses 7.00%.

Check 1: propagate prints every line twice

With one handler on the root logger and another on a child logger, a single child.info("hello") produced 2 lines. Setting child.propagate to False brought it back to 1.

The official wording: "Child loggers propagate messages up to the handlers associated with their ancestor loggers," with the off switch described as "setting the *propagate* attribute of a logger to False". The matching line in Logger.callHandlers() in logging/__init__.py on this machine is if not c.propagate:, which stops the walk upward.

What makes this awkward is that it only fires when both sides have a handler. You add a StreamHandler in your own module, the framework already attached one to root, and now every line appears twice with identical text, level and timestamp — which reads like a retry rather than a duplicate.

Check 2: basicConfig is a no-op once someone else configured logging

Measured: after attaching a handler to root, calling logging.basicConfig(filename=...) did not create the target file at all. No lines were written and no error was raised.

The gate in the source is a single if len(root.handlers) == 0:, and the function's own docstring says "This function does nothing if the root logger already has handlers". Overriding it requires force=True, which I verified in three steps: the first call with force=True created one.log, a second call without it left two.log nonexistent, and a third call with force=True created three.log.

There is a sneakier trigger. The HOWTO notes that module-level functions such as logging.warning() "will call basicConfig() for you if it has not been called yet". So if any third-party library makes a module-level logging call before your entry point runs, the root logger is already occupied, and your basicConfig() call is dead from that moment on.

Check 3: fileConfig disables your early loggers, and the effective level goes down

Measured on a logger named early.created: before fileConfig() it had disabled=False and getEffectiveLevel() of 30; after the call, disabled=True while getEffectiveLevel() had become 10.

That is the counterintuitive part: it does not silence you by raising the level — the level actually drops to 10 (DEBUG). What stops the records is the disabled flag. So the usual reflex of calling setLevel(logging.DEBUG) does nothing; the level is already low enough and disabled sits in front of it. The gate in Logger.handle() on this machine reads if (not self.disabled) and self.filter(record):.

The HOWTO warning says it plainly: the function "takes a default parameter, disable_existing_loggers, which defaults to True for reasons of backward compatibility", and it "will cause any non-root loggers existing before the fileConfig() call to be disabled". inspect.signature(logging.config.fileConfig) here agrees: (fname, defaults=None, disable_existing_loggers=True, encoding=None).

The symptom: every library that imported and created a logger before fileConfig() goes quiet all at once. Pass disable_existing_loggers=False, or move to dictConfig() and set that key explicitly — it defaults to True there as well.

Check 4: RotatingFileHandler keeps far less history than you think

Measured with maxBytes=1024 and backupCount=2 after writing 200 lines: app.log at 336 bytes (8 lines, first line line-0192, last line line-0199), app.log.1 at 1008 bytes, app.log.2 at 1008 bytes.

Numbering runs opposite to what most people assume: app.log is always the newest slice, higher numbers are older, .2 is the oldest, and .2 is also what gets deleted on the next rotation. doRollover() calls self.rotate(...) first and then removes the tail under if self.backupCount > 0:.

So "the log is rotating" and "the log is still there" are different statements. In row two of the table, 1800 lines left 180, roughly 10%. With maxBytes at 4 KB and lines around 50 bytes, one file holds about 80 lines and three files hold 240 — a ceiling fixed by your configuration, unrelated to free disk space.

Check 5: the Cookbook says multi-process writes are not supported

The Logging Cookbook is blunt: "logging to a single file from *multiple processes* is *not* supported, because there is no standard way to serialize access to a single file across multiple processes in Python," followed by "The stdlib FileHandler and subclasses do not make use of multiprocessing."

The measurements back both sentences, in two layers:

Loss without rotation. Six subprocesses each building their own FileHandler on the same path returned 1674 of 1800 lines, 7.00% short. The logging lock is in-process; nothing protects the file across processes.
Worse with rotation, and silently. Six subprocesses each building a RotatingFileHandler left 220 lines in one run and 200 in another (concurrent rotation timing is not deterministic). Their stderr held real exceptions: PermissionError: [WinError 5] and FileNotFoundError: [WinError 2], with stacks pointing at emit() → doRollover() → os.remove(dfn) in handlers.py.

None of those exceptions terminate the program. The HOWTO has a section on exactly this: "The logging package is designed to swallow exceptions which occur while logging in production." Exceptions inside emit() go to handleError(), which checks raiseExceptions: true means print a traceback to sys.stderr, false means swallow it. The default is True per the HOWTO, and it is True here too, which is why you see --- Logging error ---. I measured raiseExceptions = False as well: stderr went completely empty — the records still vanished, only the hint disappeared with them.

The two official escape routes are QueueHandler plus a dedicated listener process or thread, or SocketHandler plus a separate receiving process. I measured a QueueListener with 4 threads writing 50 lines each and got 200 of 200 back. With ProcessPoolExecutor the Cookbook tells you to build the queue as multiprocessing.Manager().Queue(-1). On Gunicorn or uWSGI it advises you to "avoid creating file-based handlers directly in your web application".

One more control: six threads in a single process sharing one RotatingFileHandler left 183 lines, in the same range as the 180 from one process, and raised nothing. That matches the first half of the Cookbook sentence — "logging is thread-safe". The lock works between threads and does nothing between processes.

Check 6: two level filters, and setting the wrong one loses everything

Measured matrix (logger.setLevel × handler.setLevel × emitting DEBUG):

Logger level	Handler level	Emitted	Result
DEBUG	DEBUG	DEBUG	printed
DEBUG	ERROR	DEBUG	nothing
ERROR	DEBUG	DEBUG	nothing

The HOWTO explains it as: "The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on."

The usual mistake: you want DEBUG in the file and INFO on the console, so you set the handler to INFO — and the file comes out empty too, because the logger is still at its default WARNING and DEBUG never reaches the handler at all. Set the logger to DEBUG and forget the handler, and you get the same silence. Both gates have to open.

Troubleshooting: 6 real errors and what actually caused them

Error 1: --- Logging error --- with TypeError: not enough arguments for format string

From lg.warning("user %s has %d points", "bob") — one argument short. The program does not crash; stderr gets --- Logging error --- and that TypeError. The mechanism is the swallowing described in Check 5. I measured logging.raiseExceptions = False turning stderr completely empty: the error vanishes, the record still disappears with it. Fix the call, and consider asserting on stderr in CI while raiseExceptions is still True.

Error 2: PermissionError: [WinError 5] Access is denied

Seen when six subprocesses rotate the same file at once, with the stack at doRollover() → os.remove(dfn) in handlers.py. Another process is holding b.log.2. Root cause is the official point in Check 5: stdlib handlers do no cross-process serialization. Move to QueueHandler with a single listener, or a third-party handler that takes a process lock.

Error 3: FileNotFoundError: [WinError 2] The system cannot find the file specified

Same scenario, different stack: the os.rename that moves b.log to b.log.1, and the os.remove of b.log.2. Two processes both decide it is time to rotate; whichever arrives first moves the file, the other finds nothing there. Also concurrent rotation, not a disk problem.

Error 4: NoneType: None

Calling logging.exception() outside an except block appends a line reading NoneType: None and no traceback. The HOWTO is direct about this method: "Call this method only from an exception handler." I measured the same call inside except ZeroDivisionError: producing the full stack normally. The reason: exception() defaults to exc_info=True, and outside a handler there is no active exception, so sys.exc_info() returns (None, None, None).

Error 5: zero lines from subprocesses under spawn

My first version started Process(...).start() at module top level, and the log directory ended up with no file at all (0 of 1800) and no error. The reason is that Windows defaults to spawn, which re-imports __main__, so the top-level code runs again in every child. Moving the startup into if __name__ == "__main__": and putting the worker function in a separate module is what produced rows four and five of the table. This one writes no log of its own, so "the directory is empty" is the only signal you get.

Error 6: AttributeError: module 'logging' has no attribute 'handlers'

From writing import logging and then using logging.handlers.RotatingFileHandler. logging.handlers is a submodule and is not imported by its parent. Import it explicitly. The interpreter even adds Did you mean: 'Handler'? — mind the case, that one is the base class in the parent module, not the submodule.

FAQ

Q: logging is thread-safe, so why are my records still missing?

Thread safety and process safety are different things. In Check 5, six threads left 183 lines, in the same range as 180 from one process, while six subprocesses left 200 and threw PermissionError. Processes are the problem.

Q: Why does basicConfig() in my entry point do nothing?

See Check 2. If root already has any handler, the call does nothing and reports nothing. Inspect logging.getLogger().handlers first, and pass force=True if you need to override.

Q: Where did the old logs go after rotation?

Into .1 and .2; higher numbers are older, and whatever exceeds backupCount is deleted on the next rotation. In the Check 4 measurement, 1800 lines ended as 180.

Q: What is the shortest fix for a multi-process setup?

Per the Cookbook: workers get only a QueueHandler, and one listener process (or thread) does the writing with a RotatingFileHandler. I measured a QueueListener returning 200 of 200 across 4 threads. With ProcessPoolExecutor, build the queue as Manager().Queue(-1).

Q: Should raiseExceptions be off in production?

The HOWTO advises you "set raiseExceptions to False for production usage". Understand the trade first: measured, that setting made Error 1 disappear from stderr entirely while records kept being dropped. Make sure something else tells you that logging itself is failing.

Limits of this article

Everything here is CPython 3.13.14 on Windows 11. File semantics differ on Linux, especially rename and delete, and I ran no cross-platform comparison. I did not test TimedRotatingFileHandler, WatchedFileHandler (documented as useful only on Unix-like systems), SysLogHandler, or any third-party handler. The SocketHandler approach is quoted from the official docs; I did not stand up a receiver on this machine. The Gunicorn and uWSGI guidance is a restatement of the official text, not a deployment I verified here.