classification
Title: incorrect and inconsistent logging in multiprocessing
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: jnoller Nosy List: Gregor_Kopka, dursobr, jnoller
Priority: normal Keywords: needs review, patch

Created on 2008-11-11 19:50 by dursobr, last changed 2009-01-18 21:13 by jnoller. This issue is now closed.

Files
File name Uploaded Description Edit
issue4301.patch jnoller, 2009-01-18 20:48
Messages (5)
msg75757 - (view) Author: Brian D'Urso (dursobr) Date: 2008-11-11 19:50
logging in multiprocessing seems to give inconsistent results on Linux
and XP, but neither appears to match the documentation:

According to the docs, when first created "the logger has level
logging.NOTSET and has a handler which sends output to sys.stderr using
format '[%(levelname)s/%(processName)s] %(message)s'" The example in the
docs also does not work, but the full problem is more clearly
illustrated with the following:

This should print a message from the main process and the subprocess:

import multiprocessing, logging

def f():
    logger = multiprocessing.get_logger()
    logger.info('info from subprocess')

if __name__ == '__main__':
    logger = multiprocessing.get_logger()
    logger.setLevel(logging.INFO)
    logger.info('info from main process')
    p = multiprocessing.Process(target=f)
    p.start()
    p.join()

but, on Windows (XP) and Linux (ScientificLinux 5.2, python 2.6 compiled
from src) it outputs only:

No handlers could be found for logger "multiprocessing"

We can 'fix' this by specifying a handler, as in:

import multiprocessing, logging

def f():
    logger = multiprocessing.get_logger()
    logger.info('info from subprocess')

if __name__ == '__main__':
    logger = multiprocessing.get_logger()
    logger.setLevel(logging.INFO)
    handler = logging.StreamHandler()
    handler.setLevel(logging.INFO)
    formatter = logging.Formatter('[%(levelname)s/%(processName)s]
%(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.info('info from main process')
    p = multiprocessing.Process(target=f)
    p.start()
    p.join()

Then on Linux I get:

[INFO/MainProcess] info from main process
[INFO/Process-1] child process calling self.run()
[INFO/Process-1] info from subprocess
[INFO/Process-1] process shutting down
[INFO/Process-1] process exiting with exitcode 0
[INFO/MainProcess] process shutting down

which looks better, but on Windows I get:

[INFO/MainProcess] info from main process
No handlers could be found for logger "multiprocessing"
[INFO/MainProcess] process shutting down

So, the logger is still not setup correctly in the subprocess on
Windows. We can again try to 'fix' this to:

import multiprocessing, logging

def f():
    logger = multiprocessing.get_logger()
    handler = logging.StreamHandler()
    handler.setLevel(logging.INFO)
    formatter = logging.Formatter('[%(levelname)s/%(processName)s]
%(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.info('info from subprocess')

if __name__ == '__main__':
    logger = multiprocessing.get_logger()
    logger.setLevel(logging.INFO)
    handler = logging.StreamHandler()
    handler.setLevel(logging.INFO)
    formatter = logging.Formatter('[%(levelname)s/%(processName)s]
%(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    logger.info('info from main process')
    p = multiprocessing.Process(target=f)
    p.start()
    p.join()

Now, on Linux I get:

[INFO/MainProcess] info from main process
[INFO/Process-1] child process calling self.run()
[INFO/Process-1] info from subprocess
[INFO/Process-1] info from subprocess
[INFO/Process-1] process shutting down
[INFO/Process-1] process shutting down
[INFO/Process-1] process exiting with exitcode 0
[INFO/Process-1] process exiting with exitcode 0
[INFO/MainProcess] process shutting down

i.e. double output from the subprocess!
On Windows, I finally get:

[INFO/MainProcess] info from main process
No handlers could be found for logger "multiprocessing"
[INFO/Process-1] info from subprocess
[INFO/Process-1] process shutting down
[INFO/Process-1] process exiting with exitcode 0
[INFO/MainProcess] process shutting down

which is almost OK, but the logger is getting set up too late to pick up
the subprocess self.run

It seems like the logger is not being setup correctly by
multiprocessing.get_logger() and the behavior is different in a
subprocess on Windows vs Linux.
msg79206 - (view) Author: Gregor Kopka (Gregor_Kopka) Date: 2009-01-05 22:51
I ran into this shortly but was able to overcome it by patching
/Lib/logging/__init__.py:

43-44:
     import threading
+    import multiprocessing
 except ImportError:

270-271:
             self.process = os.getpid()
+            self.processName = multiprocessing.current_process()._name
         else:

(and some info about %(processName)s into the docstring) to make it
usable for me.

After that the following works like intended:


import multiprocessing
import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s
%(processName)s %(threadName)s %(levelname)s  %(message)s')

# omit next line to get only what your code is logging
logger = multiprocessing.get_logger()

def f():
    logging.info('info from subprocess')

if __name__ == '__main__':
    logging.info('info from main process')
    p = multiprocessing.Process(target=f)
    p.start()
    p.join()


Surely no perfect solution, but the monkey-patching in
multiprocessing.util._check_logger_class() dosn't seem to do the trick.

Other option is to not use %(processName)s in logging format, but
%(process)s instead - then it works without patching the logging module
(but you get numeric process IDs):


import multiprocessing

import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(process)s
%(threadName)s %(levelname)s  %(message)s')

# omit next line to get only what your code is logging
logger = multiprocessing.get_logger()

def f():
    logging.info('info from subprocess')

if __name__ == '__main__':
    logging.info('info from main process')
    p = multiprocessing.Process(target=f)
    p.start()
    p.join()


2009-01-05 23:48:02,046 4000 MainThread INFO  info from main process
2009-01-05 23:48:02,187 3968 MainThread INFO  child process calling
self.run()
2009-01-05 23:48:02,187 3968 MainThread INFO  info from subprocess
2009-01-05 23:48:02,187 3968 MainThread INFO  process shutting down
2009-01-05 23:48:02,187 3968 MainThread DEBUG  running all "atexit"
finalizers with priority >= 0
2009-01-05 23:48:02,187 3968 MainThread DEBUG  running the remaining
"atexit" finalizers
2009-01-05 23:48:02,203 3968 MainThread INFO  process exiting with
exitcode 0
2009-01-05 23:48:02,203 4000 Dummy-1 INFO  process shutting down
2009-01-05 23:48:02,203 4000 Dummy-1 DEBUG  running all "atexit"
finalizers with priority >= 0
2009-01-05 23:48:02,203 4000 Dummy-1 DEBUG  running the remaining
"atexit" finalizers
msg80122 - (view) Author: Jesse Noller (jnoller) * (Python committer) Date: 2009-01-18 20:36
This is a patch to fix the logging module, and remove the crufty code in 
multiprocessing.
msg80124 - (view) Author: Jesse Noller (jnoller) * (Python committer) Date: 2009-01-18 20:48
remove the import, not needed. switch to the property
msg80127 - (view) Author: Jesse Noller (jnoller) * (Python committer) Date: 2009-01-18 21:13
fixed in r68737, merged to py3k in 68740
History
Date User Action Args
2009-01-18 21:13:15jnollersetstatus: open -> closed
resolution: fixed
messages: + msg80127
2009-01-18 20:54:51jnollersetfiles: - issue4301.patch
2009-01-18 20:48:07jnollersetfiles: + issue4301.patch
messages: + msg80124
2009-01-18 20:47:47jnollersetmessages: - msg80123
2009-01-18 20:44:57jnollersetfiles: + issue4301.patch
messages: + msg80123
2009-01-18 20:44:31jnollersetfiles: - issue4301.patch
2009-01-18 20:36:43jnollersetkeywords: + needs review, patch
files: + issue4301.patch
messages: + msg80122
2009-01-05 22:51:25Gregor_Kopkasetnosy: + Gregor_Kopka
messages: + msg79206
2008-11-11 21:54:16benjamin.petersonsetassignee: jnoller
nosy: + jnoller
2008-11-11 19:50:53dursobrcreate