1

If I have interpreted the python3 documentation correctly, regardless of where I add the handler to the root logger, my log messages from within a Process should be sent to a file. However, this is not the case.

Here is a complete program which demonstrates the problem:

import logging
import logging.handlers

from multiprocessing import Process
from time import sleep

fileHandler = logging.FileHandler( 'mylog.log' )
fileHandler.setLevel( 5 )

logger = logging.getLogger( None )

def process_logger():

    print( "process waiting" )
    sleep( 5 )
    print( 'process start' )

    logger = logging.getLogger( None )

    for num in range( 1, 10 ):
        logger.critical( "critical: %d" % num )
        sleep(1)

#
# if this is where the handler is added, the critical messages
# will go to the file
#
logger.addHandler( fileHandler )

processLogger = Process( target=process_logger )
processLogger.start()

#
# if this is where the handler is added, the critical messages
# will not go to the file.
#
#logger.addHandler( fileHandler )

print( "started" )

I am using python 3.4.3 on OS X 10.10.4.

My guess as to why this does not work is that when I start the Process, it makes a copy of the current environment and if the handler has not been added by that time, the environment the Process is running in won't have it.

I have three questions:

  1. Why do my messages not always end up in the file regardless of where I call logger.addHandler?

  2. Should my messages always end up in the file?

  3. If they should not, what is the best solution to the general problem of needed to manipulate handlers after a Process has been started?

ericg
  • 8,413
  • 9
  • 43
  • 77

1 Answers1

3

The behaviour you see is due to how processes work on POSIX. Multiprocessing on POSIX generally uses the fork system call, which happens when you create a another process via the Process(...) call. At this point, the created process is a copy of the original process. When you add the handler before the Process(...) call, the copy also has the handler already added, so process_logger (which is called in the copy) will behave as expected. When you add the handler after the Process(...) call, the handler has not been added in the copy, so process_logger (which is called in the copy) will not behave as expected.

To avoid this sort of problem, ensure that logging is configured as desired in each process (normally, this means doing the logging configuration in code which is called (directly or indirectly) from the target=XXX callable which is passed to Process. In your case, that's process_logger.

Update: See this post for more information on using logging with multiprocessing.

Vinay Sajip
  • 95,872
  • 14
  • 179
  • 191
  • The python documentation says that when one calls logger.getLogger with the same identifier that one gets the same instance of the logger. I would guess that in the case of a Process this is not the case. I would have to assume that the handlers attached to that Process are different as well. So, do you know if pointing the two file handlers at the same file as I am doing is expected to work or not? The documentation would seem to indicate yes, but how loggers work with a Process seems to be a bit unclear in the documentation. – ericg Jul 27 '15 at 11:59
  • If you can add a reference to your blog post http://plumberjack.blogspot.co.uk/2010/09/using-logging-with-multiprocessing.html, I will mark it as the answer. – ericg Jul 27 '15 at 13:24