Multiprocessing logging under Windows

[paulj3]

BPO	12954
Nosy	@applio

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2015-02-10.16:06:46.397>
created_at = <Date 2011-09-09.23:26:48.921>
labels = ['type-bug', 'invalid', 'docs']
title = 'Multiprocessing logging under Windows'
updated_at = <Date 2015-02-10.16:06:46.395>
user = 'https://bugs.python.org/paulj3'

bugs.python.org fields:

activity = <Date 2015-02-10.16:06:46.395>
actor = 'davin'
assignee = 'docs@python'
closed = True
closed_date = <Date 2015-02-10.16:06:46.397>
closer = 'davin'
components = ['Documentation']
creation = <Date 2011-09-09.23:26:48.921>
creator = 'paul.j3'
dependencies = []
files = []
hgrepos = []
issue_num = 12954
keywords = []
message_count = 10.0
messages = ['143815', '221575', '221581', '222294', '225222', '225253', '225269', '225271', '225288', '235693']
nosy_count = 5.0
nosy_names = ['docs@python', 'BreamoreBoy', 'paul.j3', 'Ari.Koivula', 'davin']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue12954'
versions = ['Python 2.7', 'Python 3.4', 'Python 3.5']

[paulj3]

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.

[BreamoreBoy]

@paul j3 can you prepare a patch for this?

[paulj3]

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.

[paulj3]

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.

[AriKoivula]

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.

[paulj3]

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?

[AriKoivula]

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.

[AriKoivula]

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.

[paulj3]

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.

[applio]

Closing per the feedback of the OP and secondary contributor to the issue. Kudos to the reporters for such nice follow-up.