logtest.py

logtest.py

from contextlib import contextmanager, closing
import logging
from logging.handlers import QueueHandler
import multiprocessing
from multiprocessing.pool import Pool
from multiprocessing.queues import Queue


@contextmanager
def background_process(x):
    try:
        x.start()
        yield x
    finally:
        x.join()


def listener_configurer():
    root = logging.getLogger()
    h = logging.StreamHandler()
    f = logging.Formatter('>> %(asctime)s%(msecs)d %(process)d %(name)s %(levelname)s %(message)s',
                          datefmt='%Y-%m-%d %H:%M:%S')
    h.setFormatter(f)
    root.addHandler(h)


def listener_process(queue, configurer):
    assert isinstance(queue, Queue)
    configurer()
    while True:
        try:
            record = queue.get()
            if record is None:
                break
            logger = logging.getLogger(record.name)
            logger.handle(record)
        except Exception as e:
            import sys
            import traceback

            print('Whoops! Problem:', file=sys.stderr)
            traceback.print_exc(file=sys.stderr)
            raise e


def worker_configurer(queue):
    h = QueueHandler(queue)
    root = logging.getLogger()
    root.addHandler(h)
    root.setLevel(logging.DEBUG)

def worker_leveltwo(x):
    try:
        logging.debug("worker level two begin, x=%s", x)
        return x * x
    finally:
        logging.debug("worker level two end, x=%s", x)

def worker_levelone(queue, configurer):
    configurer(queue)
    try:
        logging.debug("worker level one begin")
        with closing(Pool(processes=4)) as pool:
            res = pool.map(worker_leveltwo,
                           [x for x in range(10)],
                           chunksize=1)
            return sum(res) * 10
    finally:
        logging.debug("worker level one end")




def main():
    logging.basicConfig(format='<< %(asctime)s%(msecs)d %(process)d %(name)s %(levelname)s %(message)s',
                        datefmt='%Y-%m-%d %H:%M:%S',
                        level=logging.DEBUG)

    logging.debug("main begin")
    try:
        logging.debug("make queue")
        queue = multiprocessing.Queue(-1)
        logging.debug("create listener")
        with background_process(
                multiprocessing.Process(target=listener_process,
                                        args=(queue, listener_configurer))
        ):  # listener

            logging.debug("create worker level one")
            with background_process(
                    multiprocessing.Process(target=worker_levelone,
                                            args=(queue, worker_configurer))
            ):  # worker
                logging.debug("main idling")

            logging.debug("destroy worker level one")

            logging.debug("stopping queue")
            queue.put_nowait(None)
        logging.debug("destroyed listener")

    finally:
        logging.debug("main end")


if __name__ == '__main__':
    main()

result-osx.txt

<< 2015-06-21 22:52:10537 44828 root DEBUG main begin
<< 2015-06-21 22:52:10537 44828 root DEBUG make queue
<< 2015-06-21 22:52:10538 44828 root DEBUG create listener
<< 2015-06-21 22:52:10540 44828 root DEBUG create worker level one
<< 2015-06-21 22:52:10541 44828 root DEBUG main idling
<< 2015-06-21 22:52:10543 44831 root DEBUG worker level one begin
<< 2015-06-21 22:52:10543 44831 root DEBUG worker level one begin
>> 2015-06-21 22:52:10543 44831 root DEBUG worker level one begin
<< 2015-06-21 22:52:10551 44832 root DEBUG worker level two begin, x=0
<< 2015-06-21 22:52:10551 44833 root DEBUG worker level two begin, x=1
<< 2015-06-21 22:52:10551 44834 root DEBUG worker level two begin, x=2
<< 2015-06-21 22:52:10552 44832 root DEBUG worker level two end, x=0
<< 2015-06-21 22:52:10553 44833 root DEBUG worker level two end, x=1
<< 2015-06-21 22:52:10552 44835 root DEBUG worker level two begin, x=3
<< 2015-06-21 22:52:10553 44834 root DEBUG worker level two end, x=2
<< 2015-06-21 22:52:10551 44832 root DEBUG worker level two begin, x=0
<< 2015-06-21 22:52:10553 44832 root DEBUG worker level two begin, x=4
>> 2015-06-21 22:52:10551 44832 root DEBUG worker level two begin, x=0
<< 2015-06-21 22:52:10554 44835 root DEBUG worker level two end, x=3
<< 2015-06-21 22:52:10551 44833 root DEBUG worker level two begin, x=1
<< 2015-06-21 22:52:10554 44832 root DEBUG worker level two end, x=4
<< 2015-06-21 22:52:10554 44833 root DEBUG worker level two begin, x=5
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=6
>> 2015-06-21 22:52:10551 44833 root DEBUG worker level two begin, x=1
<< 2015-06-21 22:52:10554 44833 root DEBUG worker level two end, x=5
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two end, x=6
<< 2015-06-21 22:52:10551 44834 root DEBUG worker level two begin, x=2
<< 2015-06-21 22:52:10554 44832 root DEBUG worker level two begin, x=7
>> 2015-06-21 22:52:10551 44834 root DEBUG worker level two begin, x=2
<< 2015-06-21 22:52:10554 44835 root DEBUG worker level two begin, x=8
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=9
<< 2015-06-21 22:52:10555 44832 root DEBUG worker level two end, x=7
<< 2015-06-21 22:52:10555 44835 root DEBUG worker level two end, x=8
<< 2015-06-21 22:52:10552 44832 root DEBUG worker level two end, x=0
<< 2015-06-21 22:52:10555 44834 root DEBUG worker level two end, x=9
>> 2015-06-21 22:52:10552 44832 root DEBUG worker level two end, x=0
<< 2015-06-21 22:52:10553 44832 root DEBUG worker level two begin, x=4
>> 2015-06-21 22:52:10553 44832 root DEBUG worker level two begin, x=4
<< 2015-06-21 22:52:10555 44831 root DEBUG worker level one end
<< 2015-06-21 22:52:10553 44833 root DEBUG worker level two end, x=1
>> 2015-06-21 22:52:10553 44833 root DEBUG worker level two end, x=1
<< 2015-06-21 22:52:10552 44835 root DEBUG worker level two begin, x=3
>> 2015-06-21 22:52:10552 44835 root DEBUG worker level two begin, x=3
<< 2015-06-21 22:52:10553 44834 root DEBUG worker level two end, x=2
>> 2015-06-21 22:52:10553 44834 root DEBUG worker level two end, x=2
<< 2015-06-21 22:52:10554 44833 root DEBUG worker level two begin, x=5
>> 2015-06-21 22:52:10554 44833 root DEBUG worker level two begin, x=5
<< 2015-06-21 22:52:10554 44832 root DEBUG worker level two end, x=4
>> 2015-06-21 22:52:10554 44832 root DEBUG worker level two end, x=4
<< 2015-06-21 22:52:10554 44835 root DEBUG worker level two end, x=3
>> 2015-06-21 22:52:10554 44835 root DEBUG worker level two end, x=3
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=6
>> 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=6
<< 2015-06-21 22:52:10554 44832 root DEBUG worker level two begin, x=7
>> 2015-06-21 22:52:10554 44832 root DEBUG worker level two begin, x=7
<< 2015-06-21 22:52:10554 44835 root DEBUG worker level two begin, x=8
>> 2015-06-21 22:52:10554 44835 root DEBUG worker level two begin, x=8
<< 2015-06-21 22:52:10554 44833 root DEBUG worker level two end, x=5
>> 2015-06-21 22:52:10554 44833 root DEBUG worker level two end, x=5
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two end, x=6
>> 2015-06-21 22:52:10554 44834 root DEBUG worker level two end, x=6
<< 2015-06-21 22:52:10555 44832 root DEBUG worker level two end, x=7
>> 2015-06-21 22:52:10555 44832 root DEBUG worker level two end, x=7
<< 2015-06-21 22:52:10555 44835 root DEBUG worker level two end, x=8
>> 2015-06-21 22:52:10555 44835 root DEBUG worker level two end, x=8
<< 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=9
>> 2015-06-21 22:52:10554 44834 root DEBUG worker level two begin, x=9
<< 2015-06-21 22:52:10555 44834 root DEBUG worker level two end, x=9
>> 2015-06-21 22:52:10555 44834 root DEBUG worker level two end, x=9
<< 2015-06-21 22:52:10555 44831 root DEBUG worker level one end
>> 2015-06-21 22:52:10555 44831 root DEBUG worker level one end
<< 2015-06-21 22:52:10655 44828 root DEBUG destroy worker level one
<< 2015-06-21 22:52:10655 44828 root DEBUG stopping queue
<< 2015-06-21 22:52:10657 44828 root DEBUG destroyed listener
<< 2015-06-21 22:52:10657 44828 root DEBUG main end

result-win.txt

<< 2015-06-21 22:52:43684 3632 root DEBUG main begin
<< 2015-06-21 22:52:43684 3632 root DEBUG make queue
<< 2015-06-21 22:52:43684 3632 root DEBUG create listener
<< 2015-06-21 22:52:43699 3632 root DEBUG create worker level one
<< 2015-06-21 22:52:43699 3632 root DEBUG main idling
<< 2015-06-21 22:52:43980 3632 root DEBUG destroy worker level one
<< 2015-06-21 22:52:43980 3632 root DEBUG stopping queue
<< 2015-06-21 22:52:43996 3632 root DEBUG destroyed listener
<< 2015-06-21 22:52:43996 3632 root DEBUG main end