From 172ca99ff3f4d2bd27f4ed0058f9beda93a370e9 Mon Sep 17 00:00:00 2001 From: Joannah nanjekye Date: Tue, 9 Jul 2019 14:43:53 -0300 Subject: [PATCH 01/11] Fix regrtest timeout for subprocesses --- Lib/test/libregrtest/main.py | 4 +++- Lib/test/libregrtest/runtest.py | 5 ++++- Lib/test/libregrtest/runtest_mp.py | 16 ++++++++++++---- Lib/test/test_os.py | 0 4 files changed, 19 insertions(+), 6 deletions(-) mode change 100644 => 100755 Lib/test/libregrtest/main.py mode change 100644 => 100755 Lib/test/libregrtest/runtest.py mode change 100644 => 100755 Lib/test/libregrtest/runtest_mp.py mode change 100644 => 100755 Lib/test/test_os.py diff --git a/Lib/test/libregrtest/main.py b/Lib/test/libregrtest/main.py old mode 100644 new mode 100755 index 87278d0c76a2a5..3cfbb4017dfb72 --- a/Lib/test/libregrtest/main.py +++ b/Lib/test/libregrtest/main.py @@ -14,7 +14,7 @@ from test.libregrtest.runtest import ( findtests, runtest, get_abs_module, STDTESTS, NOTTESTS, PASSED, FAILED, ENV_CHANGED, SKIPPED, RESOURCE_DENIED, - INTERRUPTED, CHILD_ERROR, TEST_DID_NOT_RUN, + INTERRUPTED, CHILD_ERROR, TEST_DID_NOT_RUN, TIMEOUT, PROGRESS_MIN_TIME, format_test_result, is_failed) from test.libregrtest.setup import setup_tests from test.libregrtest.pgo import setup_pgo_tests @@ -115,6 +115,8 @@ def accumulate_result(self, result, rerun=False): self.run_no_tests.append(test_name) elif ok == INTERRUPTED: self.interrupted = True + elif ok == TIMEOUT: + self.bad.append(test_name) else: raise ValueError("invalid test result: %r" % ok) diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py old mode 100644 new mode 100755 index a43b7666cd1e35..78a567f3173c9a --- a/Lib/test/libregrtest/runtest.py +++ b/Lib/test/libregrtest/runtest.py @@ -25,6 +25,7 @@ INTERRUPTED = -4 CHILD_ERROR = -5 # error in a child process TEST_DID_NOT_RUN = -6 +TIMEOUT = -7 _FORMAT_TEST_RESULT = { PASSED: '%s passed', @@ -35,6 +36,7 @@ INTERRUPTED: '%s interrupted', CHILD_ERROR: '%s crashed', TEST_DID_NOT_RUN: '%s run no tests', + TIMEOUT: '%s test did not finish', } # Minimum duration of a test to display its duration or to mention that @@ -66,7 +68,7 @@ def is_failed(result, ns): ok = result.result - if ok in (PASSED, RESOURCE_DENIED, SKIPPED, TEST_DID_NOT_RUN): + if ok in (PASSED, RESOURCE_DENIED, SKIPPED, TEST_DID_NOT_RUN, TIMEOUT): return False if ok == ENV_CHANGED: return ns.fail_env_changed @@ -179,6 +181,7 @@ def runtest(ns, test_name): FAILED test failed PASSED test passed EMPTY_TEST_SUITE test ran no subtests. + TIMEOUT test failed due to timeout If ns.xmlpath is not None, xml_data is a list containing each generated testsuite element. diff --git a/Lib/test/libregrtest/runtest_mp.py b/Lib/test/libregrtest/runtest_mp.py old mode 100644 new mode 100755 index aa2409b4ef7985..9bc56085fea3b6 --- a/Lib/test/libregrtest/runtest_mp.py +++ b/Lib/test/libregrtest/runtest_mp.py @@ -13,7 +13,7 @@ from test.libregrtest.runtest import ( runtest, INTERRUPTED, CHILD_ERROR, PROGRESS_MIN_TIME, - format_test_result, TestResult, is_failed) + format_test_result, TestResult, is_failed, TIMEOUT) from test.libregrtest.setup import setup_tests from test.libregrtest.utils import format_duration @@ -137,6 +137,13 @@ def kill(self): popen.stdout.close() popen.stderr.close() + def time_result(self, test_name, error_type): + test_time = time.monotonic() - self.start_time + result = TestResult(test_name, error_type, test_time, None) + stdout = stderr = '' + err_msg = None + return result, stdout, stderr, err_msg + def _runtest(self, test_name): try: self.start_time = time.monotonic() @@ -154,7 +161,9 @@ def _runtest(self, test_name): raise ExitThread try: - stdout, stderr = popen.communicate() + stdout, stderr = popen.communicate(timeout=self.ns.timeout) + except subprocess.TimeoutExpired: + result, stdout, stderr, err_msg = self.time_result(test_name, TIMEOUT) except OSError: if self._killed: # kill() has been called: communicate() fails @@ -191,8 +200,7 @@ def _runtest(self, test_name): err_msg = "Failed to parse worker JSON: %s" % exc if err_msg is not None: - test_time = time.monotonic() - self.start_time - result = TestResult(test_name, CHILD_ERROR, test_time, None) + result, stdout, stderr, err_msg = self.time_result(test_name, CHILD_ERROR) return MultiprocessResult(result, stdout, stderr, err_msg) diff --git a/Lib/test/test_os.py b/Lib/test/test_os.py old mode 100644 new mode 100755 From 35b87eb63979b1d781f7b485b717b722563c6c50 Mon Sep 17 00:00:00 2001 From: Joannah nanjekye Date: Tue, 9 Jul 2019 16:32:12 -0300 Subject: [PATCH 02/11] Some edits to test --- Lib/test/libregrtest/runtest_mp.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/Lib/test/libregrtest/runtest_mp.py b/Lib/test/libregrtest/runtest_mp.py index 9bc56085fea3b6..10d7c7ce0edd68 100755 --- a/Lib/test/libregrtest/runtest_mp.py +++ b/Lib/test/libregrtest/runtest_mp.py @@ -163,7 +163,12 @@ def _runtest(self, test_name): try: stdout, stderr = popen.communicate(timeout=self.ns.timeout) except subprocess.TimeoutExpired: + if self._killed: + # kill() has been called: communicate() fails + # on reading closed stdout/stderr + raise ExitThread result, stdout, stderr, err_msg = self.time_result(test_name, TIMEOUT) + raise except OSError: if self._killed: # kill() has been called: communicate() fails From d8df7acdee47f089cc0d81a3dec7461a39090862 Mon Sep 17 00:00:00 2001 From: "blurb-it[bot]" <43283697+blurb-it[bot]@users.noreply.github.com> Date: Tue, 9 Jul 2019 19:38:29 +0000 Subject: [PATCH 03/11] =?UTF-8?q?=F0=9F=93=9C=F0=9F=A4=96=20Added=20by=20b?= =?UTF-8?q?lurb=5Fit.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst diff --git a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst new file mode 100644 index 00000000000000..dac25a828a32d3 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst @@ -0,0 +1 @@ +Fix `regrtest` timeout for subprocesses. \ No newline at end of file From a55a6af64daddb2670844caa320cbeb73fb3da20 Mon Sep 17 00:00:00 2001 From: nanjekyejoannah Date: Thu, 18 Jul 2019 12:36:37 -0300 Subject: [PATCH 04/11] Revert file mode changes --- Lib/test/libregrtest/main.py | 0 Lib/test/libregrtest/runtest.py | 4 ++-- Lib/test/libregrtest/runtest_mp.py | 0 Lib/test/test_os.py | 0 .../next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst | 1 - .../next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst | 3 +++ 6 files changed, 5 insertions(+), 3 deletions(-) mode change 100755 => 100644 Lib/test/libregrtest/main.py mode change 100755 => 100644 Lib/test/libregrtest/runtest.py mode change 100755 => 100644 Lib/test/libregrtest/runtest_mp.py mode change 100755 => 100644 Lib/test/test_os.py delete mode 100644 Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst create mode 100644 Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst diff --git a/Lib/test/libregrtest/main.py b/Lib/test/libregrtest/main.py old mode 100755 new mode 100644 diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py old mode 100755 new mode 100644 index 78a567f3173c9a..b24015af009a09 --- a/Lib/test/libregrtest/runtest.py +++ b/Lib/test/libregrtest/runtest.py @@ -36,7 +36,7 @@ INTERRUPTED: '%s interrupted', CHILD_ERROR: '%s crashed', TEST_DID_NOT_RUN: '%s run no tests', - TIMEOUT: '%s test did not finish', + TIMEOUT: '%s timed out', } # Minimum duration of a test to display its duration or to mention that @@ -181,7 +181,7 @@ def runtest(ns, test_name): FAILED test failed PASSED test passed EMPTY_TEST_SUITE test ran no subtests. - TIMEOUT test failed due to timeout + TIMEOUT test timd out. If ns.xmlpath is not None, xml_data is a list containing each generated testsuite element. diff --git a/Lib/test/libregrtest/runtest_mp.py b/Lib/test/libregrtest/runtest_mp.py old mode 100755 new mode 100644 diff --git a/Lib/test/test_os.py b/Lib/test/test_os.py old mode 100755 new mode 100644 diff --git a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst deleted file mode 100644 index dac25a828a32d3..00000000000000 --- a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-3753.GX7s8S.rst +++ /dev/null @@ -1 +0,0 @@ -Fix `regrtest` timeout for subprocesses. \ No newline at end of file diff --git a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst new file mode 100644 index 00000000000000..aa5f0f495ed01e --- /dev/null +++ b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst @@ -0,0 +1,3 @@ +The change only impacts "python3 -m test -jN --timeout=TIMEOUT", +it ensures that a worker process is stopped with a timeout if it +runs longer than `TIMEOUT` seconds. From fcb7b7376c1be23592ed8732a1e624a64dfe9b79 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 31 Jul 2019 18:18:19 +0200 Subject: [PATCH 05/11] Report stdout/stderr on timeout or child error Adjust timeouts: * timeout x 1.5 for worker process * timeout x 2.0 for main process --- Lib/test/libregrtest/runtest_mp.py | 46 +++++++++++++++++++----------- 1 file changed, 30 insertions(+), 16 deletions(-) diff --git a/Lib/test/libregrtest/runtest_mp.py b/Lib/test/libregrtest/runtest_mp.py index 10d7c7ce0edd68..eed643291162e5 100644 --- a/Lib/test/libregrtest/runtest_mp.py +++ b/Lib/test/libregrtest/runtest_mp.py @@ -103,11 +103,12 @@ class ExitThread(Exception): class MultiprocessThread(threading.Thread): - def __init__(self, pending, output, ns): + def __init__(self, pending, output, ns, timeout): super().__init__() self.pending = pending self.output = output self.ns = ns + self.timeout = timeout self.current_test_name = None self.start_time = None self._popen = None @@ -126,6 +127,12 @@ def __repr__(self): return '<%s>' % ' '.join(info) def kill(self): + """ + Kill the current process (if any). + + This method can be called by the thread running the process, + or by another thread. + """ self._killed = True popen = self._popen @@ -136,13 +143,13 @@ def kill(self): # does not hang popen.stdout.close() popen.stderr.close() + popen.wait() - def time_result(self, test_name, error_type): + def mp_result_error(self, test_name, error_type, stdout='', stderr='', + err_msg=None): test_time = time.monotonic() - self.start_time result = TestResult(test_name, error_type, test_time, None) - stdout = stderr = '' - err_msg = None - return result, stdout, stderr, err_msg + return MultiprocessResult(result, stdout, stderr, err_msg) def _runtest(self, test_name): try: @@ -161,14 +168,19 @@ def _runtest(self, test_name): raise ExitThread try: - stdout, stderr = popen.communicate(timeout=self.ns.timeout) + stdout, stderr = popen.communicate(timeout=self.timeout) except subprocess.TimeoutExpired: if self._killed: # kill() has been called: communicate() fails # on reading closed stdout/stderr raise ExitThread - result, stdout, stderr, err_msg = self.time_result(test_name, TIMEOUT) - raise + + popen.kill() + stdout, stderr = popen.communicate() + self.kill() + + return self.mp_result_error(test_name, TIMEOUT, + stdout, stderr) except OSError: if self._killed: # kill() has been called: communicate() fails @@ -177,7 +189,6 @@ def _runtest(self, test_name): raise except: self.kill() - popen.wait() raise retcode = popen.wait() @@ -205,7 +216,7 @@ def _runtest(self, test_name): err_msg = "Failed to parse worker JSON: %s" % exc if err_msg is not None: - result, stdout, stderr, err_msg = self.time_result(test_name, CHILD_ERROR) + return self.mp_result_error(test_name, CHILD_ERROR, stdout, stderr, err_msg) return MultiprocessResult(result, stdout, stderr, err_msg) @@ -249,13 +260,16 @@ def __init__(self, regrtest): self.output = queue.Queue() self.pending = MultiprocessIterator(self.regrtest.tests) if self.ns.timeout is not None: - self.test_timeout = self.ns.timeout * 1.5 + self.worker_timeout = self.ns.timeout * 1.5 + self.main_timeout = self.ns.timeout * 2.0 else: - self.test_timeout = None + self.worker_timeout = None + self.main_timeout = None self.workers = None def start_workers(self): - self.workers = [MultiprocessThread(self.pending, self.output, self.ns) + self.workers = [MultiprocessThread(self.pending, self.output, + self.ns, self.worker_timeout) for _ in range(self.ns.use_mp)] print("Run tests in parallel using %s child processes" % len(self.workers)) @@ -287,8 +301,8 @@ def _get_result(self): return None while True: - if self.test_timeout is not None: - faulthandler.dump_traceback_later(self.test_timeout, exit=True) + if self.main_timeout is not None: + faulthandler.dump_traceback_later(self.main_timeout, exit=True) # wait for a thread timeout = max(PROGRESS_UPDATE, PROGRESS_MIN_TIME) @@ -356,7 +370,7 @@ def run_tests(self): print() self.regrtest.interrupted = True finally: - if self.test_timeout is not None: + if self.main_timeout is not None: faulthandler.cancel_dump_traceback_later() # a test failed (and --failfast is set) or all tests completed From e5863739639355221ef4366ec64ef44219fdf6e0 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Thu, 1 Aug 2019 18:01:21 +0200 Subject: [PATCH 06/11] Rewrite the NEWS entry --- .../next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst index aa5f0f495ed01e..aaf1052bd3c1bd 100644 --- a/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst +++ b/Misc/NEWS.d/next/Library/2019-07-09-19-38-26.bpo-37531.GX7s8S.rst @@ -1,3 +1,2 @@ -The change only impacts "python3 -m test -jN --timeout=TIMEOUT", -it ensures that a worker process is stopped with a timeout if it -runs longer than `TIMEOUT` seconds. +"python3 -m test -jN --timeout=TIMEOUT" now kills a worker process if it runs +longer than *TIMEOUT* seconds. From 522555fc0120f1978a7fe624a451b2c36ab22b54 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 14 Aug 2019 12:03:39 +0200 Subject: [PATCH 07/11] format_test_result(): add timeout duration --- Lib/test/libregrtest/runtest.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py index b24015af009a09..3f5c87b913c573 100644 --- a/Lib/test/libregrtest/runtest.py +++ b/Lib/test/libregrtest/runtest.py @@ -13,7 +13,7 @@ from test import support from test.libregrtest.refleak import dash_R, clear_caches from test.libregrtest.save_env import saved_test_environment -from test.libregrtest.utils import print_warning +from test.libregrtest.utils import format_duration, print_warning # Test result constants. @@ -77,7 +77,10 @@ def is_failed(result, ns): def format_test_result(result): fmt = _FORMAT_TEST_RESULT.get(result.result, "%s") - return fmt % result.test_name + text = fmt % result.test_name + if result.result == TIMEOUT: + text = '%s (%s)' % (text, format_duration(result.test_time)) + return text def findtestdir(path=None): From 96bbeb303b0071b2686c57246dc4c3a876591001 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 14 Aug 2019 12:13:16 +0200 Subject: [PATCH 08/11] Add an unit test --- Lib/test/test_regrtest.py | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/Lib/test/test_regrtest.py b/Lib/test/test_regrtest.py index fdab8c8ef5d155..e9ac4e6575ad5f 100644 --- a/Lib/test/test_regrtest.py +++ b/Lib/test/test_regrtest.py @@ -1154,6 +1154,30 @@ def test_garbage(self): env_changed=[testname], fail_env_changed=True) + def test_multiprocessing_timeout(self): + code = textwrap.dedent(r""" + import time + import unittest + try: + import faulthandler + except ImportError: + faulthandler = None + + class Tests(unittest.TestCase): + def test_sleep(self): + # we want to test regrtest multiprocessing timeout, + # not faulthandler timeout + if faulthandler is not None: + faulthandler.cancel_dump_traceback_later() + + time.sleep(60 * 5) + """) + testname = self.create_test(code=code) + + output = self.run_tests("-j2", "--timeout=1.0", testname, exitcode=2) + self.check_executed_tests(output, [testname], + failed=testname) + def test_unraisable_exc(self): # --fail-env-changed must catch unraisable exception code = textwrap.dedent(r""" From e2b32804a5a826157eac1945dc2cb6e7ed4aec95 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 14 Aug 2019 12:51:02 +0200 Subject: [PATCH 09/11] Enhance unit test Check that the test timed out --- Lib/test/test_regrtest.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/Lib/test/test_regrtest.py b/Lib/test/test_regrtest.py index e9ac4e6575ad5f..931f125eb8f9eb 100644 --- a/Lib/test/test_regrtest.py +++ b/Lib/test/test_regrtest.py @@ -1164,6 +1164,7 @@ def test_multiprocessing_timeout(self): faulthandler = None class Tests(unittest.TestCase): + # test hangs and so should be stopped by the timeout def test_sleep(self): # we want to test regrtest multiprocessing timeout, # not faulthandler timeout @@ -1177,6 +1178,8 @@ def test_sleep(self): output = self.run_tests("-j2", "--timeout=1.0", testname, exitcode=2) self.check_executed_tests(output, [testname], failed=testname) + self.assertRegex(output, + re.compile('%s timed out' % testname, re.MULTILINE)) def test_unraisable_exc(self): # --fail-env-changed must catch unraisable exception From 46bfdfe0cdc9715885f01f5cf215d59ba58f378a Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 14 Aug 2019 12:52:09 +0200 Subject: [PATCH 10/11] Fix typo --- Lib/test/libregrtest/runtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py index 3f5c87b913c573..548e65808f60a9 100644 --- a/Lib/test/libregrtest/runtest.py +++ b/Lib/test/libregrtest/runtest.py @@ -184,7 +184,7 @@ def runtest(ns, test_name): FAILED test failed PASSED test passed EMPTY_TEST_SUITE test ran no subtests. - TIMEOUT test timd out. + TIMEOUT test timed out. If ns.xmlpath is not None, xml_data is a list containing each generated testsuite element. From f06ae0be40daf5c19470a0464af5dba4267670e5 Mon Sep 17 00:00:00 2001 From: Victor Stinner Date: Wed, 14 Aug 2019 12:54:15 +0200 Subject: [PATCH 11/11] Fix is_failed(): TIMEOUT is considered as a fail --- Lib/test/libregrtest/runtest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py index 548e65808f60a9..e7dce180cb3753 100644 --- a/Lib/test/libregrtest/runtest.py +++ b/Lib/test/libregrtest/runtest.py @@ -68,7 +68,7 @@ def is_failed(result, ns): ok = result.result - if ok in (PASSED, RESOURCE_DENIED, SKIPPED, TEST_DID_NOT_RUN, TIMEOUT): + if ok in (PASSED, RESOURCE_DENIED, SKIPPED, TEST_DID_NOT_RUN): return False if ok == ENV_CHANGED: return ns.fail_env_changed