classification
Title: sporadic test_subprocess failure
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: tim.peters Nosy List: pitrou, python-dev, tim.peters
Priority: normal Keywords:

Created on 2013-10-25 21:23 by pitrou, last changed 2013-10-26 01:48 by tim.peters. This issue is now closed.

Messages (5)
msg201296 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-10-25 21:23
It looks like this may be the symptom of a buglet in Thread.join:

======================================================================
ERROR: test_communicate_timeout (test.test_subprocess.ProcessTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\test\test_subprocess.py", line 672, in test_communicate_timeout
    timeout=0.3)
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\unittest\case.py", line 689, in assertRaises
    return context.handle('assertRaises', callableObj, args, kwargs)
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\unittest\case.py", line 158, in handle
    callable_obj(*args, **kwargs)
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\subprocess.py", line 947, in communicate
    stdout, stderr = self._communicate(input, endtime, timeout)
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\subprocess.py", line 1193, in _communicate
    self.stdout_thread.join(self._remaining_time(endtime))
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\threading.py", line 1062, in join
    self._wait_for_tstate_lock(timeout=timeout)
  File "E:\home\cpython\buildslave\x86\3.x.snakebite-win2k8r2sp1-x86\build\lib\threading.py", line 1074, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
ValueError: timeout value must be strictly positive
msg201297 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-10-25 21:36
Well, when a timeout is specified, .join() passes exactly the timeout passed to _it_ to ._wait_for_tstate_lock(), which in turn passes exactly the same timeout to .acquire().  So the negative value must be coming from _communicate() (the

    self.stdout_thread.join(self._remaining_time(endtime))

line).

_remaining_time() in turn:

    def _remaining_time(self, endtime):
        """Convenience for _communicate when computing timeouts."""
        if endtime is None:
            return None
        else:
            return endtime - _time()

So that just subtracts and doesn't do anything to ensure the result is positive, nor does the calling site check the return value.  Most other _remaining_time() calls in subprocess.py *do* check the return value, so I think this is clearly a subprocess.py bug.
msg201298 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-10-25 21:41
BTW, if subprocess did check the return value, it would see that the timeout already expired, and the test would pass.
msg201307 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-10-26 01:32
I think I'll change Thread.join() to just return if a timeout <= 0 is passed.  The docs don't say anything about what Thread.join() does with a negative timeout, but at least in 2.7.5 it happened to just return.  No point being gratuitously more demanding ;-)
msg201308 - (view) Author: Roundup Robot (python-dev) Date: 2013-10-26 01:47
New changeset af67cfcd4089 by Tim Peters in branch 'default':
Issue #19399: fix sporadic test_subprocess failure.
http://hg.python.org/cpython/rev/af67cfcd4089
History
Date User Action Args
2013-10-26 01:48:04tim.peterssetstatus: open -> closed
type: behavior
resolution: fixed
stage: resolved
2013-10-26 01:47:26python-devsetnosy: + python-dev
messages: + msg201308
2013-10-26 01:40:55tim.peterssetassignee: tim.peters
2013-10-26 01:32:41tim.peterssetmessages: + msg201307
2013-10-25 21:41:08tim.peterssetmessages: + msg201298
2013-10-25 21:36:24tim.peterssetmessages: + msg201297
2013-10-25 21:23:25pitroucreate