Python multiprocessing+logging.FileHandler

Question

I'm trying to implement logging in multiprocessing server. According to the documentation, "logging to a single file from multiple processes is not supported". I've created a small program to check this statement:

import logging
import multiprocessing
import os

log = logging.getLogger()


def setup_logger():
    formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s: %(message)s')

    fileHandler = logging.FileHandler('test.log')
    fileHandler.setFormatter(formatter)

    log.setLevel(logging.DEBUG)
    log.addHandler(fileHandler)


def write_log_entries(identifier, start_event):
    start_event.wait()
    for i in range(100):
        s = ''.join(str(identifier) for k in range(30))
        log.info('[{}, {}] --- {}'.format(os.getpid(), identifier, s))


if __name__ == '__main__':
    setup_logger()
    procs = []
    start_event = multiprocessing.Event()
    for i in range(100, 300):
        p = multiprocessing.Process(target=write_log_entries, args=(i, start_event))
        procs.append(p)

    for p in procs:
        p.start()

    start_event.set()

    for p in procs:
        p.join()

After executing the above code I expected to see a complete mess in "test.log", but everything seems to be fine (except timestamps, of course, which are not in sequence).

Can anybody explain why don't log entries overlap when the log file is being written by multiple processes simultaneously? Can log.info() be considered atomic in this case?

related: [Logging to a single file from multiple processes](http://docs.python.org/dev/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes) — jfs, Sep 02 '12 at 19:46
note: `setup_logger()` is called only in the main process. On Windows `log` won't be configured where copy-on-write is not used. — jfs, Sep 02 '12 at 19:51
I suggest using syslog(), because io operations are slow and it is a good to offload them to something like rsyslog daemon. The only drawback i think is that standard libc syslog() call by default truncates data - only first 2048 will be logged. But you can workaround that writing your own syslog() call that will write in syslog format to standard(or non standard) socket. — SanityIO, Sep 02 '12 at 20:40
I also cannot reproduce any garbling in any way. I'm on linux and logging lines of 400 KB to a file. Never observe any problem. Has anybody found a way to observe such garbling? — Michele Piccolini, Sep 16 '20 at 13:35

score 11 · Accepted Answer · answered Sep 02 '12 at 19:25

Short answer: the kernel locks single calls to write, so you're OK as long as the messages are small, so they get flushed in a single write, and this write succeeds in writing everything at once. There is no general guarantee that this is the case, which is why the docs don't promise that this will work at all.

Long answer: Each call to log.info flushes the log output. This is necessary, or you wouldn't be able to see the latest log entries in the file. On the Python/libc level, flush is implemented as a call to the write(2) syscall, which is invoked to write out the contents of the file's buffer, if any. In your case, the buffer contents is your log message. So, Python or libc, depending on which file is being used, ends up calling the OS call such as:

write(fd, buf, buflen);

...where fd is the system-level file descriptor of the log file, buf is the memory where the write was buffered, and buflen is the length of the message. (You can see these calls if you trace your Python process with a tool such as strace on Linux.) write returns the number of characters successfully written, and the kernel will not interleave those characters with other writes in the same region of the file. If the file is opened in O_APPEND mode, the writes are even guaranteed to be at the end of file, at least on Unix. So, if buflen is small, as is the case with normal log messages, everything is fine. But at least two things can go wrong.

First, there is no guarantee that all of buflen will be written out in a single write. write can be interrupted by a signal, fd can point to a device that accepts writes of fixed size, or your log message may be large enough for the kernel not to accept it in a single chunk. Normally, this wouldn't be a problem—correctly written write is always implemented as a loop. But in your case, this would be a disaster, because the different calls to write would interleave with other processes.

Second, if your log message is large enough that it doesn't fit in the stdio buffer (8K or so), then it will be split into chunks before it ever reaches the kernel. This can easily happen when logging tracebacks, or when formatting logs into verbose format like XML.

Thanks, this explanation made things clear. I'll try to implement some kind of multiprocessing-aware FileHandler then, as suggested in the docs. — user1642265, Sep 02 '12 at 19:46
"Each call to log.info flushes the log output." Could you provide a reference where it is promised? — jfs, Sep 02 '12 at 19:56
I haven't seen it explicitly promised, but a logging framework that didn't do this would not be very useful. The whole point of logging is that you can look at the log with external tools (including something as simple as `tail -f`) to see what is going on with your application. — user4815162342, Sep 02 '12 at 20:00
To clarify this last point: on Linux, regular files are fully buffered by default, and stdio buffer size is 8K. If `flush` didn't get called, you'd only see a log file entry after 8K of messages have been written. This is corroborated by the actual code, take a look at `StreamHandler.emit`. stdio buffering is a neat feature to prevent spurious writes, but it is just an optimization. An `emit` that held on to buffered data any longer than absolutely necessary (such as by the end of the method invocation) would be seriously buggy - a log message stuck in a stream buffer is of no use to anyone. — user4815162342, Sep 02 '12 at 20:10
your assumptions are reasonable and valid for the case in question but they are incorrect in general case e.g., there is [`MemoryHandler`](http://docs.python.org/dev/library/logging.handlers.html#logging.handlers.MemoryHandler) that doesn't flush all messages immediately. — jfs, Sep 02 '12 at 20:46
@user1642265 You might want to have a look at: http://stackoverflow.com/questions/641420/how-should-i-log-while-using-multiprocessing-in-python — Thomas Orozco, Sep 02 '12 at 20:56
Yes, the very concept of "flushing" doesn't apply for some handlers, such as `MemoryHandler`. I mentioned flushing in the context of explaining the seemingly correct behavior of `FileHandler`. — user4815162342, Sep 03 '12 at 05:06

Python multiprocessing+logging.FileHandler

1 Answers1