test_queue_feeder_donot_stop_onexc() of test_multiprocessing_spawn fails randomly on x86 Windows7 3.x

[vstinner]

BPO	30595
Nosy	@pfmoore, @vstinner, @tjguk, @zware, @zooba, @applio, @grzgrzgrz3
PRs	bpo-30595: Increase test_queue_feeder_donot_stop_onexc() timeout #2026 bpo-30595: Fix multiprocessing.Queue.get(timeout) #2027 bpo-30595: Increase test_queue_feeder_donot_stop_onexc() timeout #2148 [3.6] bpo-30595: Fix multiprocessing.Queue.get(timeout) (#2027) #2881 [2.7] bpo-30595: Fix multiprocessing.Queue.get(timeout) #2883 [2.7] bpo-30595: Increase test_queue_feeder_donot_stop_onexc() timeout (#2148) #5429

^{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.15:54:28.860>
created_at = <Date 2017-06-08.07:40:26.663>
labels = ['3.7', 'tests', 'OS-windows']
title = 'test_queue_feeder_donot_stop_onexc() of test_multiprocessing_spawn fails randomly on x86 Windows7 3.x'
updated_at = <Date 2018-01-29.16:16:17.462>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-01-29.16:16:17.462>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-07-26.15:54:28.860>
closer = 'vstinner'
components = ['Tests', 'Windows']
creation = <Date 2017-06-08.07:40:26.663>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 30595
keywords = []
message_count = 15.0
messages = ['295385', '295520', '295525', '295527', '295528', '295631', '295632', '295633', '295855', '295961', '299201', '299243', '299244', '311145', '311146']
nosy_count = 7.0
nosy_names = ['paul.moore', 'vstinner', 'tim.golden', 'zach.ware', 'steve.dower', 'davin', 'grzgrzgrz3']
pr_nums = ['2026', '2027', '2148', '2881', '2883', '5429']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue30595'
versions = ['Python 2.7', 'Python 3.6', 'Python 3.7']

[vstinner]

http://buildbot.python.org/all/builders/x86%20Windows7%203.x/builds/712/steps/test/logs/stdio

======================================================================
ERROR: test_queue_feeder_donot_stop_onexc (test.test_multiprocessing_spawn.WithProcessesTestQueue)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\_test_multiprocessing.py", line 767, in test_queue_feeder_donot_stop_onexc
    self.assertTrue(q.get(timeout=0.1))
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\multiprocessing\queues.py", line 105, in get
    raise Empty
queue.Empty

[vstinner]

Hum, it may be a regression a recent change like the commit bc50f03:
bpo-30414: multiprocessing.Queue._feed do not break from main loop on exc (bpo-1683)

[grzgrzgrz3]

Looks like build bot is too slow for timeout=0.1.

I am guessing 0.1 is too low because we have wrong condition in Queue.get.

It should be.

diff --git a/Lib/multiprocessing/queues.py b/Lib/multiprocessing/queues.py
index dda03dd..42e9884 100644
--- a/Lib/multiprocessing/queues.py
+++ b/Lib/multiprocessing/queues.py
@@ -101,7 +101,7 @@ class Queue(object):
             try:
                 if block:
                     timeout = deadline - time.time()
-                    if timeout < 0 or not self._poll(timeout):
+                    if self._poll(timeout):
                         raise Empty
                 elif not self._poll():
                     raise Empty

If we successfully acquired self._rlock, we should poll no matter how long acquire took.

[grzgrzgrz3]

of course it should be if not:

diff --git a/Lib/multiprocessing/queues.py b/Lib/multiprocessing/queues.py
index dda03dd..514f991 100644
--- a/Lib/multiprocessing/queues.py
+++ b/Lib/multiprocessing/queues.py
@@ -101,7 +101,7 @@ class Queue(object):
             try:
                 if block:
                     timeout = deadline - time.time()
-                    if timeout < 0 or not self._poll(timeout):
+                    if not self._poll(timeout):
                         raise Empty
                 elif not self._poll():
                     raise Empty

[vstinner]

I am guessing 0.1 is too low because we have wrong condition in Queue.get. It should be.

I'm not sure that the buildbot took this code path, but I like your suggestion. Checking the reader in non-blocking mode is cheap.

poll() with timeout < 0 works as poll(0), I checked the UNIX and Windows implementations.

So I proposed your change as a PR, and credited you ;-)
#2027

[vstinner]

New changeset 1b7863c by Victor Stinner in branch 'master':
bpo-30595: Fix multiprocessing.Queue.get(timeout) (bpo-2027)
1b7863c

[vstinner]

Thanks Grzegorz Grzywacz! I commited your idea of fix. Let's if it fixes the issue. It will be hard to check since it seems like the bug was random.

Later, I will backport the fix to other branches.

[vstinner]

Let's *see* if it fixes the issue. It will be hard to check since it seems
like the bug was random.

[vstinner]

New changeset 1b7863c by Victor Stinner in branch 'master':
bpo-30595: Fix multiprocessing.Queue.get(timeout) (bpo-2027)
1b7863c

While this change is a nice fix, it isn't enough to make the test stable on slow buildbot: it failed again on the same buildbot,
http://buildbot.python.org/all/builders/x86%20Windows7%203.x/builds/744

If I modify the timeout from 100 ms to 1 ms, the test also fail on Linux on my laptop. So I proposed #2148 to increase the timeout from 100 ms to 1 sec.

[vstinner]

New changeset 8f6eeaf by Victor Stinner in branch 'master':
bpo-30595: Increase test_queue_feeder_donot_stop_onexc() timeout (bpo-2148)
8f6eeaf

[vstinner]

New changeset e42339d by Victor Stinner in branch '3.6':
[3.6] bpo-30595: Fix multiprocessing.Queue.get(timeout) (bpo-2027) (bpo-2881)
e42339d

[vstinner]

New changeset ec9a712 by Victor Stinner in branch '2.7':
[3.6] bpo-30595: Fix multiprocessing.Queue.get(timeout) (bpo-2027) (bpo-2881) (bpo-2883)
ec9a712