mplog: Python advanced multiprocessing logging.

example.py

import logging
import multiprocessing
import time

import mplog

FORMAT = '%(asctime)s - %(processName)s - %(levelname)s - %(message)s'
logging.basicConfig(level=logging.DEBUG, format=FORMAT)
existing_logger = logging.getLogger('x')


def subprocess(n):
    existing_logger.info('y')
    logger = logging.getLogger('sub')
    logger.info('Before sleep.')
    time.sleep(0.01)
    logger.info('After sleep.')

    root = logging.getLogger()
    root.debug('Root log message.')


def start_processes(log_queue):
    procs = list()
    for i in xrange(5):
        proc = multiprocessing.Process(target=mplog.logged_call,
                                       args=(log_queue, subprocess, i))
        proc.start()
        procs.append(proc)

    for proc in procs:
        proc.join()


def main():
    existing_logger.info('Before')
    with mplog.open_queue() as log_queue:
        existing_logger.info('In context manager.')
        start_processes(log_queue)
        existing_logger.info('At the end.')

    logging.info('Now really quitting.')


if __name__ == '__main__':
    main()

mplog.py

import contextlib
import multiprocessing
import logging
import threading


def daemon(log_queue):
    while True:
        try:
            record_data = log_queue.get()
            if record_data is None:
                break
            record = logging.makeLogRecord(record_data)

            logger = logging.getLogger(record.name)
            if logger.isEnabledFor(record.levelno):
                logger.handle(record)
        except (KeyboardInterrupt, SystemExit):
            raise
        except EOFError:
            break
        except:
            logging.exception('Error in log handler.')


class MPLogger(logging.Logger):
    log_queue = None

    def isEnabledFor(self, level):
        return True

    def handle(self, record):
        ei = record.exc_info
        if ei:
            # to get traceback text into record.exc_text
            logging._defaultFormatter.format(record)
            record.exc_info = None  # not needed any more
        d = dict(record.__dict__)
        d['msg'] = record.getMessage()
        d['args'] = None
        self.log_queue.put(d)


def logged_call(log_queue, func, *args, **kwargs):
    MPLogger.log_queue = log_queue
    logging.setLoggerClass(MPLogger)
    # monkey patch root logger and already defined loggers
    logging.root.__class__ = MPLogger
    for logger in logging.Logger.manager.loggerDict.values():
        if not isinstance(logger, logging.PlaceHolder):
            logger.__class__ = MPLogger
    func(*args, **kwargs)


@contextlib.contextmanager
def open_queue():
    log_queue = multiprocessing.Queue()
    daemon_thread = threading.Thread(target=daemon, args=(log_queue,))
    daemon_thread.start()
    yield log_queue
    log_queue.put(None)

output.txt

$ python example.py
2013-10-16 09:27:16,526 - MainProcess - INFO - Before
2013-10-16 09:27:16,545 - MainProcess - INFO - In context manager.
2013-10-16 09:27:16,634 - Process-1 - INFO - y
2013-10-16 09:27:16,634 - Process-1 - INFO - Before sleep.
2013-10-16 09:27:16,637 - Process-2 - INFO - y
2013-10-16 09:27:16,638 - Process-2 - INFO - Before sleep.
2013-10-16 09:27:16,644 - Process-1 - INFO - After sleep.
2013-10-16 09:27:16,644 - Process-1 - DEBUG - Root log message.
2013-10-16 09:27:16,645 - Process-3 - INFO - y
2013-10-16 09:27:16,645 - Process-3 - INFO - Before sleep.
2013-10-16 09:27:16,648 - Process-2 - INFO - After sleep.
2013-10-16 09:27:16,648 - Process-2 - DEBUG - Root log message.
2013-10-16 09:27:16,651 - Process-4 - INFO - y
2013-10-16 09:27:16,651 - Process-4 - INFO - Before sleep.
2013-10-16 09:27:16,655 - Process-3 - INFO - After sleep.
2013-10-16 09:27:16,655 - Process-3 - DEBUG - Root log message.
2013-10-16 09:27:16,661 - Process-4 - INFO - After sleep.
2013-10-16 09:27:16,661 - Process-4 - DEBUG - Root log message.
2013-10-16 09:27:16,684 - Process-5 - INFO - y
2013-10-16 09:27:16,684 - Process-5 - INFO - Before sleep.
2013-10-16 09:27:16,694 - Process-5 - INFO - After sleep.
2013-10-16 09:27:16,694 - Process-5 - DEBUG - Root log message.
2013-10-16 09:27:16,697 - MainProcess - INFO - At the end.
2013-10-16 09:27:16,697 - MainProcess - INFO - Now really quitting.