test_multiprocessing_spawn leaves processes running in background

[vadmium]

BPO	26762
Nosy	@pitrou, @vstinner, @vadmium, @serhiy-storchaka, @applio
PRs	bpo-26762: test_multiprocessing detects dangling per test case class #2841 bpo-26762: Avoid daemon process in _test_multiprocessing #2842 bpo-26762: test_multiprocessing: Fix dangling process/thread #2850 bpo-26762: test_multiprocessing close more queues #2855 [3.6] bpo-26762, bpo-31019: Backport multiprocessing fixes from master to 3.6 #2879 bpo-26762: _test_multiprocessing reports dangling #3064

^{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 2017-07-26.02:53:22.774>
created_at = <Date 2016-04-15.04:04:25.162>
labels = ['type-bug', 'tests']
title = 'test_multiprocessing_spawn leaves processes running in background'
updated_at = <Date 2017-08-10.15:36:53.689>
user = 'https://github.com/vadmium'

bugs.python.org fields:

activity = <Date 2017-08-10.15:36:53.689>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-07-26.02:53:22.774>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2016-04-15.04:04:25.162>
creator = 'martin.panter'
dependencies = []
files = []
hgrepos = []
issue_num = 26762
keywords = []
message_count = 21.0
messages = ['263442', '263461', '298877', '298952', '298954', '298955', '298957', '298959', '298988', '299004', '299008', '299009', '299010', '299024', '299033', '299034', '299036', '299037', '299188', '299190', '300104']
nosy_count = 5.0
nosy_names = ['pitrou', 'vstinner', 'martin.panter', 'serhiy.storchaka', 'davin']
pr_nums = ['2841', '2842', '2850', '2855', '2879', '3064']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue26762'
versions = ['Python 3.5', 'Python 3.6']

[vadmium]

I noticed that this test leaves processes running in the background for a moment after the parent Python process exits. They disappear pretty quickly, but even so, it seems like a bad design. However I am not familiar with the multiprocessing module, so maybe this is unavoidable.

$ ps
  PID TTY          TIME CMD
  597 pts/2    00:00:01 bash
13423 pts/2    00:00:00 ps
$ python3.5 -m test test_multiprocessing_spawn; ps
[1/1] test_multiprocessing_spawn
1 test OK.
  PID TTY          TIME CMD
  597 pts/2    00:00:01 bash
13429 pts/2    00:00:00 python3.5
13475 pts/2    00:00:00 python3.5
15066 pts/2    00:00:00 ps

[vstinner]

Using this patch, I can see the list of "python" processes slowly growing:

diff -r ad5b079565ad Lib/unittest/case.py
--- a/Lib/unittest/case.py      Tue Apr 12 23:15:44 2016 -0700
+++ b/Lib/unittest/case.py      Fri Apr 15 11:06:07 2016 +0200
@@ -10,6 +10,7 @@ import warnings
 import collections
 import contextlib
 import traceback
+import os
 
 from . import result
 from .util import (strclass, safe_repr, _count_diff_all_purpose,
@@ -590,6 +591,7 @@ class TestCase(object):
         expecting_failure = expecting_failure_class or expecting_failure_method
         outcome = _Outcome(result)
         try:
+            os.system("ps")
             self._outcome = outcome
 
             with outcome.testPartExecutor(self):
@@ -614,6 +616,7 @@ class TestCase(object):
                         self._addUnexpectedSuccess(result)
                 else:
                     result.addSuccess(self)
+            os.system("ps")
             return result
         finally:
             result.stopTest(self)

[pitrou]

I'm not able to reproduce. Can you try again with latest master?

[vstinner]

I'm not sure that the issue is really fixed. I applied my msg263461 patch and I still see the list of "python" processes growing but then also a little bit decreasing, and some zombi <defunct> processes.

The problem is that it's hard to guess if a growing "ps" list is a bug or not, since we only cleanup things in tearDownClass(), not in tearDown(). So it's ok to keep some child processes between two unit tests.

I wrote a first change to help debugging the issue. My change adds more warnings and calls support.reap_children():
#2841

With this PR, the following test fails:
---
haypo@selma$ ./python -u -m test -v --fail-env-changed --match=test.test_multiprocessing_spawn.WithThreadsTestPool.test_release_task_refs --match=test.test_multiprocessing_spawn.WithProcessesTestLogging.test_level test_multiprocessing_spawn
== CPython 3.7.0a0 (heads/master:b364d9f, Jul 24 2017, 11:06:33) [GCC 6.3.1 20161221 (Red Hat 6.3.1-1)]
== Linux-4.11.9-200.fc25.x86_64-x86_64-with-fedora-25-Twenty_Five little-endian
== hash algorithm: siphash24 64bit
== cwd: /home/haypo/prog/python/master/build/test_python_24433
== CPU count: 4
== encodings: locale=UTF-8, FS=utf-8
Testing with flags: sys.flags(debug=0, inspect=0, interactive=0, optimize=0, dont_write_bytecode=0, no_user_site=0, no_site=0, ignore_environment=0, verbose=0, bytes_warning=0, quiet=0, hash_randomization=1, isolated=0)
Run tests sequentially
0:00:00 load avg: 0.27 [1/1] test_multiprocessing_spawn
test_level (test.test_multiprocessing_spawn.WithProcessesTestLogging) ... ok
Warning -- reap_children() reaped child process 24437
test_release_task_refs (test.test_multiprocessing_spawn.WithThreadsTestPool) ... ok
Warning -- reap_children() reaped child process 24438
Dangling processes: {<Process(Process-2, started daemon)>, <Process(Process-1, started daemon)>}

----------------------------------------------------------------------
Ran 2 tests in 1.369s

OK
Warning -- multiprocessing.process._dangling was modified by test_multiprocessing_spawn
Before: <_weakrefset.WeakSet object at 0x7fdc24f70058>
After: <_weakrefset.WeakSet object at 0x7fdc2a666260>
test_multiprocessing_spawn failed (env changed)

1 test altered the execution environment:
test_multiprocessing_spawn

Total duration: 2 sec
Tests result: ENV CHANGED
---

[vstinner]

With this PR, the following test fails:

Ah, it seems like test_level() alone is enough to reproduce the bug and the following PR fixes it:
#2842

[vstinner]

With PR 2841 + PR 2842, there is still at least one test which leaks processes:

---

$ ./python -m test --match=test_notify_all -v test_multiprocessing_spawn
== CPython 3.7.0a0 (heads/master:b364d9f, Jul 24 2017, 11:06:33) [GCC 6.3.1 20161221 (Red Hat 6.3.1-1)]
== Linux-4.11.9-200.fc25.x86_64-x86_64-with-fedora-25-Twenty_Five little-endian
== hash algorithm: siphash24 64bit
== cwd: /home/haypo/prog/python/master/build/test_python_28469
== CPU count: 4
== encodings: locale=UTF-8, FS=utf-8
Testing with flags: sys.flags(debug=0, inspect=0, interactive=0, optimize=0, dont_write_bytecode=0, no_user_site=0, no_site=0, ignore_environment=0, verbose=0, bytes_warning=0, quiet=0, hash_randomization=1, isolated=0)
Run tests sequentially
0:00:00 load avg: 0.44 [1/1] test_multiprocessing_spawn
test_notify_all (test.test_multiprocessing_spawn.WithManagerTestCondition) ... ok
test_notify_all (test.test_multiprocessing_spawn.WithProcessesTestCondition) ... ok
Warning -- reap_children() reaped child process 28553
Warning -- reap_children() reaped child process 28557
Warning -- reap_children() reaped child process 28559
Warning -- reap_children() reaped child process 28561
test_notify_all (test.test_multiprocessing_spawn.WithThreadsTestCondition) ... ok
Dangling processes: {<Process(Process-11, started daemon)>, <Process(Process-12, started daemon)>, <Process(Process-13, started daemon)>, <Process(Process-9, started daemon)>}

---

Ran 3 tests in 3.772s

OK
Warning -- multiprocessing.process._dangling was modified by test_multiprocessing_spawn
Before: <_weakrefset.WeakSet object at 0x7f2385200400>
After: <_weakrefset.WeakSet object at 0x7f238a8ff260>
test_multiprocessing_spawn failed (env changed)

1 test altered the execution environment:
test_multiprocessing_spawn

Total duration: 4 sec
Tests result: SUCCESS
---

I looked at the code of the test: it's full of "p.daemon = True" and "t.daemon = True", whereas these processes and threads are not tracked in a list to be cleared manually, so I'm not surprised of the warnings.

[vstinner]

New changeset 0663495 by Victor Stinner in branch 'master':
bpo-26762: Avoid daemon process in _test_multiprocessing (bpo-2842)
0663495

[vstinner]

If you want to use --fail-env-changed with PR 2841, for example to use test.bisect, you may want this extra patch:

diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py
index f2342c3..5f9e5c3 100644
--- a/Lib/test/_test_multiprocessing.py
+++ b/Lib/test/_test_multiprocessing.py
@@ -4352,6 +4352,7 @@ class ManagerMixin(object):
                       "children after %s seconds"
                       % (multiprocessing.active_children(), dt),
                       file=sys.stderr)
+                test.support.environment_altered = True
                 break
 
         gc.collect()                       # do garbage collection
@@ -4359,6 +4360,7 @@ class ManagerMixin(object):
             # This is not really an error since some tests do not
             # ensure that all processes which hold a reference to a
             # managed object have been joined.
+            test.support.environment_altered = True
             print('Warning -- Shared objects which still exist at manager '
                   'shutdown:')
             print(cls.manager._debug_info())

[vstinner]

Antoine Pitrou: "I'm not able to reproduce. Can you try again with latest master?"

Oh, maybe I found why... There is a tearDownModule() function which hides bugs. Try following change:

diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py
index 88e2eb3..ae77468 100644
--- a/Lib/test/_test_multiprocessing.py
+++ b/Lib/test/_test_multiprocessing.py
@@ -4432,8 +4432,8 @@ def install_tests_in_module_dict(remote_globs, start_method):
     def tearDownModule():
         multiprocessing.set_start_method(old_start_method[0], force=True)
         # pause a bit so we don't get warning about dangling threads/processes
-        time.sleep(0.5)
-        multiprocessing.process._cleanup()
+        # time.sleep(0.5)
+        # multiprocessing.process._cleanup()
         gc.collect()
         tmp = set(multiprocessing.process._dangling) - set(dangling[0])
         if tmp:

[vstinner]

I just created bpo-31019 "multiprocessing.Pool should join "dead" processes" to fix dangling processes related to pool, like test.test_multiprocessing_spawn.WithProcessesTestPool.test_context.

[vstinner]

I rewrote PR 2841 to detect more bugs.

[vstinner]

PR 2850 + PR 2849 (of bpo-31019) fix most dangling process/thread, but one specific test still leaks:

test.test_multiprocessing_spawn.WithProcessesTestPool.test_traceback

I will try to fix it once other bugs are fixed.

[vstinner]

Using PR 2841, I wrote a tool to run each test in subprocess to check if a test method leaks. I found these methods:

./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestBarrier.test_thousand
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestCondition.test_notify
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestEvent.test_event
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestPool.test_context
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestProcess.test_close
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestQueue.test_fork
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestQueue.test_qsize
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestQueue.test_queue_feeder_donot_stop_onexc
./python -m test --fail-env-changed test_multiprocessing_spawn -v --match test.test_multiprocessing_spawn.WithProcessesTestPool.test_traceback