why python logging RotatingFileHandler lost records when used in multiple processes?

Question

Recently I've realize that my application generate less log records than I expected. After some experiments I've found that problem is in RotatingFileHandler and multiprocessing.

import logging
from logging import handlers
from multiprocessing import Pool
import os


log_file_name = 'log.txt'
def make_logger():
    logger = logging.getLogger('my_logger')
    logger.setLevel(logging.INFO)

    current_handler_names = {handler.name for handler in logger.handlers}
    handler_name = 'my_handler'
    if handler_name in current_handler_names:
        return logger

    handler = handlers.RotatingFileHandler(
        log_file_name, maxBytes=10 * 2 ** 10, backupCount=0)
    handler.setLevel(logging.INFO)
    handler.set_name(handler_name)

    logger.addHandler(handler)

    return logger



def f(x):
    logger = make_logger()
    logger.info('hey %s' % x)


if os.path.exists(log_file_name):
    os.unlink(log_file_name)

p = Pool(processes=30)
N = 1000
p.map(f, range(N))
with open(log_file_name, 'r') as f:
    print 'expected: %s, real: %s' % (N, f.read().count('hey'))

Output:

$ python main.py
expected: 1000, real: 943

What I did wrong?

Answer 1

As it is well explained,

Although logging is thread-safe, and logging to a single file from multiple threads in a single process is supported, logging to a single file from multiple processes is not supported

In a few words, RotatingFileHandler simply closes and deletes the file from one process, then opens a new file. But other processes don't know about a new file descriptor and see that previous have been closed. Only the process who managed to rotate the file first continues logging.

In my answer to the similar question I've proposed to use logrotate daemon to rotate files aside of these processes. It does not close the file descriptor, but just truncates the file. Thus file remains the same and other processes can continue logging.