[issue4301] incorrect and inconsistent logging in multiprocessing

[Gregor Kopka]

Gregor Kopka <mailfrom-bugs.python.org at kopka.net> added the comment:

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

----------
nosy: +Gregor_Kopka

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue4301>
_______________________________________