classification
Title: Multiprocessing logging under Windows
Type: behavior Stage: resolved
Components: Documentation Versions: Python 3.4, Python 3.5, Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: docs@python Nosy List: Ari.Koivula, BreamoreBoy, davin, docs@python, paul.j3
Priority: normal Keywords:

Created on 2011-09-09 23:26 by paul.j3, last changed 2015-02-10 16:06 by davin. This issue is now closed.

Messages (10)
msg143815 - (view) Author: paul j3 (paul.j3) * (Python triager) Date: 2011-09-09 23:26
The Windows programming guidelines for the multiprocessing module documentation should include a warning that any logging initialization should be protected by the 'if __name__' block.  Otherwise you will get duplicate logging entries for the child processes.  This is because the multiprocessing.forking.prepare() function explicitly calls log_to_stderr(), and may implicitly do so again when it imports the parent module, resulting in duplicate logging handlers.
msg221575 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2014-06-25 21:38
@paul j3 can you prepare a patch for this?
msg221581 - (view) Author: paul j3 (paul.j3) * (Python triager) Date: 2014-06-25 22:36
It will take a while to reconstruct the circumstances behind this issue.  I think I was working through some online class examples, working in the Eclipse pydev environment.  Currently I'm mostly working in linux, and not doing much with multiprocessing.  Looks like most, if not all, the examples are already protected with the 'if __name__' clause.
msg222294 - (view) Author: paul j3 (paul.j3) * (Python triager) Date: 2014-07-04 16:59
The documentation currently warns
https://docs.python.org/2/library/multiprocessing.html#windows

> Safe importing of main module

> Make sure that the main module can be safely imported by a new Python interpreter without causing unintended side effects (such a starting a new process).

The logging duplication that I mentioned here is one of those side effects.  So there's probably no need for further warnings.
msg225222 - (view) Author: Ari Koivula (Ari.Koivula) Date: 2014-08-12 08:56
I encountered this problem on Python 3.2.5 on Windows and don't think a vague warning about initializing modules is a proper solution. A better solution would be to simply not add multiple handlers, even if log_to_stderr is called more than once.
msg225253 - (view) Author: paul j3 (paul.j3) * (Python triager) Date: 2014-08-13 03:52
I added a print line to a 'windows' example from the documentation:

    from multiprocessing import Process
    print 'importing multiprocessing'
    def foo():
        print 'hello'
    p = Process(target=foo)
    p.start()

Run with Python 2.7.0 on linux I get

    importing multiprocessing
    hello

Run with same, but on Windows I get

    importing multiprocessing
    importing multiprocessing
    hello
    importing multiprocessing
    hello
    (recursively)

Now if I put the last part into an if:

    if __name__ == '__main__':
        p = Process(target=foo)
        p.start()

the Windows version no longer recurses, but I still get the double print message.

In linux the child process is created with `os.fork`, which makes a copy of the parent.  The script is only loaded and run once.

In windows, the child is created by issuing a new call to Python with the script.  The script is loaded and run by the child as well as the parent, hence the double print.

So any action that you don't want run when the child is created should be in the 'if __name__' block.

I can picture modifying the log_to_stderr function so that it checks the logger's 'handlers' list for one that already writes to stderr.  It should be easy to add to your own code.  But isn't it easier just to segregate all the 'main' actions from the 'child' ones?
msg225269 - (view) Author: Ari Koivula (Ari.Koivula) Date: 2014-08-13 08:29
Guarding the initialization is indeed correct and works, but log_to_stderr adding the handler multiple times is still annoying. Especially as you probably do want it to be called for child processes (at least on windows) and it might be called during initialization in multiprocessing.forking.prepare (but not on windows).

There is no need to go through the handlers. Just avoid adding the handler again if it has already been added. There actually already is a variable (multiprocessing.util._log_to_stderr) that tracks this, but it isn't used.
msg225271 - (view) Author: Ari Koivula (Ari.Koivula) Date: 2014-08-13 09:46
Actually, multiprocessing.forking.prepare does call log_to_stderr on windows. While debugging the double handler issue I somehow came to the conclusion that it didn't, but it seems to work just fine now. I must have been doing something weird like creating the processes before setting the log level to cause that.

This issue can probably be closed.
msg225288 - (view) Author: paul j3 (paul.j3) * (Python triager) Date: 2014-08-13 21:56
I had noticed the `global _log_to_stderr` in `util.log_to_stderr()`, but hadn't taken time to track down where it is used.

Not only is it passed from the 'util' module to the 'forking' one, but it is also passed via a piped pickle from parent to child process.

There's a lot more to simulating 'os.fork' in Windows than I would have guessed.
msg235693 - (view) Author: Davin Potts (davin) * (Python committer) Date: 2015-02-10 16:06
Closing per the feedback of the OP and secondary contributor to the issue.  Kudos to the reporters for such nice follow-up.
History
Date User Action Args
2015-02-10 16:06:46davinsetstatus: open -> closed

nosy: + davin
messages: + msg235693

resolution: not a bug
stage: resolved
2014-08-13 21:56:35paul.j3setmessages: + msg225288
2014-08-13 09:46:55Ari.Koivulasetmessages: + msg225271
2014-08-13 08:29:32Ari.Koivulasetmessages: + msg225269
2014-08-13 03:52:43paul.j3setmessages: + msg225253
2014-08-12 08:56:48Ari.Koivulasetnosy: + Ari.Koivula
messages: + msg225222
2014-07-04 16:59:12paul.j3setmessages: + msg222294
2014-06-25 22:36:38paul.j3setmessages: + msg221581
2014-06-25 21:38:30BreamoreBoysetversions: + Python 2.7, Python 3.4, Python 3.5
nosy: + BreamoreBoy

messages: + msg221575

type: behavior
2011-09-09 23:26:48paul.j3create