Python Logging with Multiprocessing in Windows

Question

I have a rather large Python project which currently runs on Linux but I am trying to expand to Windows. I've reduced the code to a full example which can be run to illustrate my problems: I have two classes, Parent and Child. Parent is initialized first, creates a logger, and spawns a Child to do work:

import logging
import logging.config
import multiprocessing

class Parent( object ):
    def __init__(self, logconfig):
        logging.config.dictConfig(logconfig)
        self.logger = logging.getLogger(__name__)

    def spawnChild(self):
        self.logger.info('One')
        c = Child(self.logger)
        c.start()

class Child(multiprocessing.Process):
    def __init__(self, logger):
        multiprocessing.Process.__init__(self)
        self.logger = logger

    def run(self):
        self.logger.info('Two')

if __name__ == '__main__':
    p = Parent({
            'version':1, 
            "handlers": {
                "console": {
                    "class": "logging.StreamHandler",
                    "stream": "ext://sys.stdout"
                },
            },
            "root": {
                "level": "DEBUG",
                "handlers": [
                    "console",
                    ]
                }
            }
        )
    p.spawnChild()

On linux (specifically, ubuntu 12.04), I get the following (expected) output:

user@ubuntu:~$ python test.py 
One
Two

But, on Windows (specifically, Windows 7), it fails with a pickling error:

C:\>python test.py
<snip>
pickle.PicklingError: Can't pickle <type 'thread.lock'>: it's not found as thread.lock

The problem comes down to Windows' lack of a true fork, so objects have to be pickled when sent between threads. But, the logger can't be pickled. I've tried using __getstate__ and __setstate__ to avoid pickling, and reference by name in Child:

def __getstate__(self):
    d = self.__dict__.copy()
    if 'logger' in d.keys():
        d['logger'] = d['logger'].name
    return d

def __setstate__(self, d):
    if 'logger' in d.keys():
        d['logger'] = logging.getLogger(d['logger'])
    self.__dict__.update(d)

This works in Linux just as before, and now Windows won't fail with the PicklingError. However, my output is only from Parent:

C:\>python test.py
One

C:\>

It seems that the child is unable to use the logger, despite no message complaining "No logger could be found for handler '__main__'" or any other error message. I've looked around and there are means by which I could completely restructure how I log in my program, but that's obviously a last resort. I'm hoping that I'm just missing something obvious, and that the wisdom of the crowd can point it out to me.

Answer 1

In most cases, Logger objects are not picklable, because they use unpicklable theading.Lock and/or file objects internally. Your attempted workaround does avoid pickling the logger, but it ends up creating a completely different Logger in the child process, which happens to have the same name as the Logger in the parent; the effects of logging.config call you made are lost. To get the behavior you want you'll need to need to recreate the logger in the child process and re-call logging.config.dictConfig:

class Parent( object ):
    def __init__(self, logconfig):
        self.logconfig = logconfig
        logging.config.dictConfig(logconfig)
        self.logger = logging.getLogger(__name__)

    def spawnChild(self):
        self.logger.info('One')
        c = Child(self.logconfig)
        c.start()

class Child(multiprocessing.Process):
    def __init__(self, logconfig):
        multiprocessing.Process.__init__(self)
        self.logconfig = logconfig

    def run(self):
        # Recreate the logger in the child
        logging.config.dictConfig(self.logconfig)
        self.logger = logging.getLogger(__name__)

        self.logger.info('Two')

Or, if you want to keep using __getstate__/__setstate__:

class Parent( object ):
    def __init__(self, logconfig):
        logging.config.dictConfig(logconfig)
        self.logger = logging.getLogger(__name__)
        self.logconfig = logconfig

    def spawnChild(self):
        self.logger.info('One')
        c = Child(self.logger, self.logconfig)
        c.start()

class Child(multiprocessing.Process):
    def __init__(self, logger, logconfig):
        multiprocessing.Process.__init__(self)
        self.logger = logger
        self.logconfig = logconfig

    def run(self):
        self.logger.info('Two')

    def __getstate__(self):
        d = self.__dict__.copy()
        if 'logger' in d:
            d['logger'] = d['logger'].name
        return d

    def __setstate__(self, d):
        if 'logger' in d:
            logging.config.dictConfig(d['logconfig'])
            d['logger'] = logging.getLogger(d['logger'])
        self.__dict__.update(d)