classification
Title: [3.5] test_first_completed_some_already_completed() of test_concurrent_futures.ProcessPoolWaitTests: time.sleep() fails with "sleep length must be non-negative" in setUp() on x86 Tiger 3.5
Type: Stage: resolved
Components: macOS, Tests Versions: Python 3.5
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: bquinlan, ned.deily, ronaldoussoren, vstinner
Priority: normal Keywords:

Created on 2017-07-04 10:19 by vstinner, last changed 2017-08-11 00:19 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 2564 merged vstinner, 2017-07-04 10:52
PR 2880 merged vstinner, 2017-07-26 02:37
Messages (5)
msg297639 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-04 10:19
Code of the setUp() method:

class ExecutorMixin:
    worker_count = 5

    def setUp(self):
        self.t1 = time.time()
        try:
            self.executor = self.executor_type(max_workers=self.worker_count)
        except NotImplementedError as e:
            self.skipTest(str(e))
        self._prime_executor()

    def _prime_executor(self):
        # Make sure that the executor is ready to do work before running the
        # tests. This should reduce the probability of timeouts in the tests.
        futures = [self.executor.submit(time.sleep, 0.1)
                   for _ in range(self.worker_count)]

        for f in futures:
            f.result()


I don't understand how the child process can fail with ValueError("sleep length must be non-negative") when running time.sleep(0.1). Code of the sleep function:

static PyObject *
time_sleep(PyObject *self, PyObject *obj)
{
    _PyTime_t secs;
    if (_PyTime_FromSecondsObject(&secs, obj, _PyTime_ROUND_CEILING))
        return NULL;
    if (secs < 0) {
        PyErr_SetString(PyExc_ValueError,
                        "sleep length must be non-negative");
        return NULL;
    }
    if (pysleep(secs) != 0)
        return NULL;
    Py_INCREF(Py_None);
    return Py_None;
}

Can it be a major rounding issue in time_sleep()? Or concurrent.futures failed completely to serialized the floating point number 0.1?


http://buildbot.python.org/all/builders/x86%20Tiger%203.5/builds/324/steps/test/logs/stdio

0:27:59 load avg: 1.54 [211/398/1] test_concurrent_futures
test_cancel (test.test_concurrent_futures.FutureTests) ... ok
test_cancelled (test.test_concurrent_futures.FutureTests) ... ok
test_done (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_already_cancelled (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_already_failed (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_already_successful (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_raises (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_with_cancel (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_with_exception (test.test_concurrent_futures.FutureTests) ... ok
test_done_callback_with_result (test.test_concurrent_futures.FutureTests) ... ok
test_exception_with_success (test.test_concurrent_futures.FutureTests) ... ok
test_exception_with_timeout (test.test_concurrent_futures.FutureTests) ... ok
test_repr (test.test_concurrent_futures.FutureTests) ... ok
test_result_with_cancel (test.test_concurrent_futures.FutureTests) ... ok
test_result_with_success (test.test_concurrent_futures.FutureTests) ... ok
test_result_with_timeout (test.test_concurrent_futures.FutureTests) ... ok
test_running (test.test_concurrent_futures.FutureTests) ... ok
test_duplicate_futures (test.test_concurrent_futures.ProcessPoolAsCompletedTests) ... 2.20s ok
test_no_timeout (test.test_concurrent_futures.ProcessPoolAsCompletedTests) ... 0.18s ok
test_zero_timeout (test.test_concurrent_futures.ProcessPoolAsCompletedTests) ... 2.20s ok
test_killed_child (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.21s ok
test_map (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.20s ok
test_map_chunksize (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.21s ok
test_map_exception (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.19s ok
test_map_timeout (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 6.18s ok
test_max_workers_negative (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.21s ok
test_no_stale_references (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.20s ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.19s ok
test_submit (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.18s ok
test_submit_keyword (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.21s ok
test_traceback (test.test_concurrent_futures.ProcessPoolExecutorTest) ... 0.20s ok
test_context_manager_shutdown (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 0.10s ok
test_del_shutdown (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 0.10s ok
test_hang_issue12364 (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 1.09s ok
test_interpreter_shutdown (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 2.13s ok
test_processes_terminate (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 0.09s ok
test_run_after_shutdown (test.test_concurrent_futures.ProcessPoolShutdownTest) ... 0.00s ok
test_all_completed (test.test_concurrent_futures.ProcessPoolWaitTests) ... 0.20s ok
test_first_completed (test.test_concurrent_futures.ProcessPoolWaitTests) ... 1.69s ok
test_first_completed_some_already_completed (test.test_concurrent_futures.ProcessPoolWaitTests) ... ERROR
test_first_exception (test.test_concurrent_futures.ProcessPoolWaitTests) ... 3.20s ok
test_first_exception_one_already_failed (test.test_concurrent_futures.ProcessPoolWaitTests) ... 2.20s ok
test_first_exception_some_already_complete (test.test_concurrent_futures.ProcessPoolWaitTests) ... 1.70s ok
test_timeout (test.test_concurrent_futures.ProcessPoolWaitTests) ... 6.18s ok
test_duplicate_futures (test.test_concurrent_futures.ThreadPoolAsCompletedTests) ... 2.11s ok
test_no_timeout (test.test_concurrent_futures.ThreadPoolAsCompletedTests) ... 0.11s ok
test_zero_timeout (test.test_concurrent_futures.ThreadPoolAsCompletedTests) ... 2.10s ok
test_default_workers (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.10s ok
test_map (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.11s ok
test_map_exception (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.11s ok
test_map_submits_without_iteration (test.test_concurrent_futures.ThreadPoolExecutorTest)
Tests verifying issue 11777. ... 0.11s ok
test_map_timeout (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 6.10s ok
test_max_workers_negative (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.10s ok
test_no_stale_references (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.10s ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.11s ok
test_submit (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.10s ok
test_submit_keyword (test.test_concurrent_futures.ThreadPoolExecutorTest) ... 0.10s ok
test_context_manager_shutdown (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 0.01s ok
test_del_shutdown (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 0.01s ok
test_hang_issue12364 (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 1.04s ok
test_interpreter_shutdown (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 1.74s ok
test_run_after_shutdown (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 0.00s ok
test_threads_terminate (test.test_concurrent_futures.ThreadPoolShutdownTest) ... 0.00s ok
test_all_completed (test.test_concurrent_futures.ThreadPoolWaitTests) ... 0.11s ok
test_first_completed (test.test_concurrent_futures.ThreadPoolWaitTests) ... 1.60s ok
test_first_completed_some_already_completed (test.test_concurrent_futures.ThreadPoolWaitTests) ... 1.60s ok
test_first_exception (test.test_concurrent_futures.ThreadPoolWaitTests) ... 3.10s ok
test_first_exception_one_already_failed (test.test_concurrent_futures.ThreadPoolWaitTests) ... 2.10s ok
test_first_exception_some_already_complete (test.test_concurrent_futures.ThreadPoolWaitTests) ... 1.60s ok
test_pending_calls_race (test.test_concurrent_futures.ThreadPoolWaitTests) ... 0.90s ok
test_timeout (test.test_concurrent_futures.ThreadPoolWaitTests) ... 6.10s ok

======================================================================
ERROR: test_first_completed_some_already_completed (test.test_concurrent_futures.ProcessPoolWaitTests)
----------------------------------------------------------------------
concurrent.futures.process._RemoteTraceback: 
"""
Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.5.bolen-tiger/build/Lib/concurrent/futures/process.py", line 175, in _process_worker
    r = call_item.fn(*call_item.args, **call_item.kwargs)
ValueError: sleep length must be non-negative
"""

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/db3l/buildarea/3.5.bolen-tiger/build/Lib/test/test_concurrent_futures.py", line 71, in setUp
    self._prime_executor()
  File "/Users/db3l/buildarea/3.5.bolen-tiger/build/Lib/test/test_concurrent_futures.py", line 87, in _prime_executor
    f.result()
  File "/Users/db3l/buildarea/3.5.bolen-tiger/build/Lib/concurrent/futures/_base.py", line 398, in result
    return self.__get_result()
  File "/Users/db3l/buildarea/3.5.bolen-tiger/build/Lib/concurrent/futures/_base.py", line 357, in __get_result
    raise self._exception
ValueError: sleep length must be non-negative

----------------------------------------------------------------------
Ran 71 tests in 65.994s

FAILED (errors=1)
Warning -- multiprocessing.process._dangling was modified by test_concurrent_futures
  Before: <_weakrefset.WeakSet object at 0x1491884>
  After:  <_weakrefset.WeakSet object at 0x1567f14> 
Warning -- threading._dangling was modified by test_concurrent_futures
  Before: <_weakrefset.WeakSet object at 0x149161c>
  After:  <_weakrefset.WeakSet object at 0x120db24> 
test test_concurrent_futures failed
msg297642 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-04 11:14
New changeset 3df9dec425b0254df1cdf41922fd8d6b08bf47e4 by Victor Stinner in branch 'master':
bpo-30845: Enhance test_concurrent_futures cleanup (#2564)
https://github.com/python/cpython/commit/3df9dec425b0254df1cdf41922fd8d6b08bf47e4
msg297747 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-05 13:44
New changeset 8207c17486baece8ed0ac42d9f8d69ecec4ba7e4 by Victor Stinner in branch 'master':
Revert "bpo-30822: Fix testing of datetime module." (#2588)
https://github.com/python/cpython/commit/8207c17486baece8ed0ac42d9f8d69ecec4ba7e4
msg299196 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-26 03:05
New changeset a6f045224a03f9b5f940c80ee142a2a4b4a9c9d8 by Victor Stinner in branch '3.6':
bpo-30845: Enhance test_concurrent_futures cleanup (#2564) (#2880)
https://github.com/python/cpython/commit/a6f045224a03f9b5f940c80ee142a2a4b4a9c9d8
msg300138 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-08-11 00:00
Python 3.5 doesn't accept bugfixes anymore, so I close this issue.
History
Date User Action Args
2017-08-11 00:19:05vstinnersetresolution: fixed -> out of date
2017-08-11 00:00:24vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg300138

stage: resolved
2017-07-26 03:05:11vstinnersetmessages: + msg299196
2017-07-26 02:37:07vstinnersetpull_requests: + pull_request2932
2017-07-05 13:44:56vstinnersetmessages: + msg297747
2017-07-04 11:14:07vstinnersetmessages: + msg297642
2017-07-04 10:52:14vstinnersetpull_requests: + pull_request2631
2017-07-04 10:19:07vstinnercreate