Fix regrtest timeout for subprocesses: regrtest -jN --timeout=SECONDS

[nanjekyejoannah]

BPO	37531
Nosy	@vstinner, @jkloth, @koobs, @eryksun, @miss-islington, @nanjekyejoannah
PRs	bpo-37531: Fix regrtest timeout for subprocesses #14679 bpo-37531: Fix regrtest timeout for subprocesses #15072 [3.8] bpo-37531: Fix regrtest timeout for subprocesses (GH-15072) #15279 [3.7] bpo-37531: Fix regrtest timeout for subprocesses (GH-15072) #15280 bpo-37531: Enhance regrtest multiprocess timeout #15345 bpo-37531: Fix regrtest _timedout() function on timeout #15419 [3.8] bpo-37531: Enhance regrtest multiprocess timeout (GH-15345) #15871 [3.7] bpo-37531: Enhance regrtest multiprocess timeout (GH-15345) #15874 bpo-37531: regrtest main process uses shorter timeout #16220 [3.7] bpo-37531: regrtest main process uses shorter timeout (GH-16220) #16223 [3.8] bpo-37531: regrtest main process uses shorter timeout (GH-16220) #16224 bpo-37531: Skip test_regrtest.test_multiprocessing_timeout() on Windows #16247 bpo-37531: Skip test_regrtest.test_multiprocessing_timeout() on all platforms #16282 [3.8] bpo-37531: sync regrtest with master branch #16285 [3.7] bpo-37531: sync regrtest with master branch (GH-16285) #16289 bpo-37531: regrtest ignores output on timeout #16659 [3.8] bpo-37531: regrtest ignores output on timeout (GH-16659) #16676 [3.7] bpo-37531: regrtest ignores output on timeout (GH-16659) #16677 bpo-37531: regrtest now catchs ProcessLookupError #16827
Files	kill_timeout.py test_kill.py

^{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 2019-10-09.15:06:10.652>
created_at = <Date 2019-07-09.19:34:22.877>
labels = ['3.8', '3.7', 'tests', '3.9', 'type-crash']
title = 'Fix regrtest timeout for subprocesses: regrtest -jN --timeout=SECONDS'
updated_at = <Date 2020-04-14.23:05:24.157>
user = 'https://github.com/nanjekyejoannah'

bugs.python.org fields:

activity = <Date 2020-04-14.23:05:24.157>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-10-09.15:06:10.652>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-07-09.19:34:22.877>
creator = 'nanjekyejoannah'
dependencies = []
files = ['48555', '48556']
hgrepos = []
issue_num = 37531
keywords = ['patch']
message_count = 51.0
messages = ['347576', '349689', '349703', '349704', '349708', '350009', '350012', '350014', '350017', '350020', '350023', '350044', '350057', '350058', '350060', '350061', '350132', '350181', '350183', '350191', '350233', '350246', '350272', '350329', '350578', '351399', '351517', '351713', '351714', '351716', '351815', '352273', '352619', '352632', '352633', '352674', '352679', '352726', '352730', '352796', '352804', '352806', '354078', '354088', '354223', '354270', '354272', '354277', '354817', '366410', '366459']
nosy_count = 7.0
nosy_names = ['vstinner', 'jkloth', 'jeremy.kloth', 'koobs', 'eryksun', 'miss-islington', 'nanjekyejoannah']
pr_nums = ['14679', '15072', '15279', '15280', '15345', '15419', '15871', '15874', '16220', '16223', '16224', '16247', '16282', '16285', '16289', '16659', '16676', '16677', '16827']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue37531'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[nanjekyejoannah]

Reported by Victor Stinner.

regrtest has a --timeout parameter which calls
faulthandler.dump_traceback_later(timeout), but sometimes it's not
enough to kill a test. regrtest should kill a worker process if it
runs longer than --timeout seconds.

• https://bugs.python.org/issue37313 : test_concurrent_futures ran for
  25 hours whereas regrtest was run using --timeout 900
• regrtest ran for 4 days whereas it was run with --timeout=900:
  https://mail.python.org/pipermail/python-buildbots/2019-June/000285.html

[vstinner]

New changeset b0c8369 by Victor Stinner in branch 'master':
bpo-37531: Fix regrtest timeout for subprocesses (GH-15072)
b0c8369

[vstinner]

New changeset 93bee6a by Victor Stinner in branch '3.7':
[3.7] bpo-37531: Fix regrtest timeout for subprocesses (GH-15072) (GH-15280)
93bee6a

[vstinner]

New changeset d85c567 by Victor Stinner in branch '3.8':
[3.8] bpo-37531: Fix regrtest timeout for subprocesses (GH-15072) (GH-15279)
d85c567

[vstinner]

Thanks Joannah! That's a nice enhancement which should help to stabilize buildbots even more.

The next step is bpo-37711: "regrtest: re-run failed tests in subprocesses".

[jkloth]

It seems that an issue still exists.

https://buildbot.python.org/all/#/builders/130/builds/1050

has been running for nearly 9 hours at this point. I can leave it "stuck" if there is some diagnostics that would be beneficial. But I would prefer not to have this impeding other testing for too long.

[vstinner]

I just tested the 3.7 branch manually: regrtest works as expected.

I'm using this local changes:

diff --git a/Lib/test/libregrtest/runtest.py b/Lib/test/libregrtest/runtest.py
index e7dce180cb..7d996d6918 100644
--- a/Lib/test/libregrtest/runtest.py
+++ b/Lib/test/libregrtest/runtest.py
@@ -119,7 +119,7 @@ def _runtest(ns, test_name):
 
     use_timeout = (ns.timeout is not None)
     if use_timeout:
-        faulthandler.dump_traceback_later(ns.timeout, exit=True)
+        pass #faulthandler.dump_traceback_later(ns.timeout, exit=True)
 
     start_time = time.perf_counter()
     try:
diff --git a/Lib/test/test_os.py b/Lib/test/test_os.py
index 8032da0530..e21399c840 100644
--- a/Lib/test/test_os.py
+++ b/Lib/test/test_os.py
@@ -89,6 +89,7 @@ class FileTests(unittest.TestCase):
     tearDown = setUp
 
     def test_access(self):
+        import time; time.sleep(3600)
         f = os.open(support.TESTFN, os.O_CREAT|os.O_RDWR)
         os.close(f)
         self.assertTrue(os.access(support.TESTFN, os.W_OK))

Then I ran:

vstinner@apu$ ./python -m test -j2 test_os -m test_access --timeout=3
Run tests in parallel using 2 child processes
0:00:04 load avg: 0.59 [1/1/1] test_os timed out (4 sec 512 ms)

== Tests result: FAILURE ==

1 test failed:
test_os

Total duration: 4 sec 545 ms
Tests result: FAILURE

As you can see, test_os is killed after 4.5 seconds, as expected (it uses timeout x 1.5, since faulthandler is supposed to be first watchdog with timeout seconds).

--

Maybe something is wrong with test_concurrent_futures on Windows. Maybe subprocess.Popen.kill() is unable to kill the process immediately for an unknown reason?

Or maybe subprocess.Popen.communicate(timeout=self.timeout) didn't fail with TimeoutExpired?

Sadly, libregrtest is quite when it kills a worker process because of timeout, since the following output should be enough to understand what happened. But here the worker was not killed, or failed to be killed, or something else...

[vstinner]

I can leave it "stuck" if there is some diagnostics that would be beneficial.

Can you check the process hierarchy? I would like to know how many worker processes are still running under the main regrtest process. I expect to see exactly one. I don't know how to investigate more on such issue on Windows.

[jeremykloth]

Can you check the process hierarchy? I would like to know how many worker processes are still running under the main regrtest process. I expect to see exactly one. I don't know how to investigate more on such issue on Windows.

There are no child processes of the main test process. There are 5
orphaned processes from multiprocessing. Their parent process is gone
(assuming the parent_pid argument is correct). There is also an
orphaned typeperf.exe process, probably also from the killed process.