test.regrtest: -jN (with N != 1) + --slow + child error or interruption = TypeError

[Arfrever]

BPO	25373
Nosy	@vstinner
Files	regrtest-2.7.patch: Patch for 2.7 regrtest-3.4.patch: Patch for 3.4 regrtest-3.5.patch: Patch for 3.5 regrtest-3.6.patch: Patch for 3.6

^{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 2015-10-11.08:41:14.697>
created_at = <Date 2015-10-11.04:34:50.956>
labels = ['tests']
title = 'test.regrtest: -jN (with N != 1) + --slow + child error or interruption = TypeError'
updated_at = <Date 2015-10-11.20:09:20.867>
user = 'https://bugs.python.org/Arfrever'

bugs.python.org fields:

activity = <Date 2015-10-11.20:09:20.867>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2015-10-11.08:41:14.697>
closer = 'python-dev'
components = ['Tests']
creation = <Date 2015-10-11.04:34:50.956>
creator = 'Arfrever'
dependencies = []
files = ['40746', '40747', '40748', '40749']
hgrepos = []
issue_num = 25373
keywords = ['patch']
message_count = 7.0
messages = ['252757', '252781', '252783', '252784', '252793', '252795', '252823']
nosy_count = 3.0
nosy_names = ['vstinner', 'Arfrever', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue25373'
versions = ['Python 3.4', 'Python 3.5', 'Python 3.6']

[Arfrever]

Function runtest() (used by single-process mode) always returns tuple with test result as integer and test time as float.
This tuple is passed as second argument to function accumulate_result(), which has (in Python 3.6):
def accumulate_result(self, test, result):
ok, test_time = result
self.test_times.append((test_time, test))

test_times is later used by code, which expects that times are floats:
if self.ns.print_slow:
self.test_times.sort(reverse=True)
print("10 slowest tests:")
for time, test in self.test_times[:10]:
print("%s: %.1fs" % (test, time))

Code used by multi-process mode can return tuple with integer and string (describing error in subprocess), which with --slow option would cause TypeError.

Example:

In terminal 1:
$ LD_LIBRARY_PATH="$(pwd)" ./python -m test.regrtest -j2 --slow test_lib2to3

In terminal 2 (sufficiently quickly):
$ kill -SIGINT $(ps aux | grep '"test_lib2to3"' | grep -v grep | awk '{print $2}')

Output in terminal 1:

Test suite interrupted by signal SIGINT.
1 test omitted:
    test_lib2to3
10 slowest tests:
Traceback (most recent call last):
  File "/tmp/cpython/Lib/runpy.py", line 170, in _run_module_as_main
    "__main__", mod_spec)
  File "/tmp/cpython/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/tmp/cpython/Lib/test/regrtest.py", line 39, in <module>
    main_in_temp_cwd()
  File "/tmp/cpython/Lib/test/libregrtest/main.py", line 451, in main_in_temp_cwd
    main()
  File "/tmp/cpython/Lib/test/libregrtest/main.py", line 429, in main
    Regrtest().main(tests=tests, **kwargs)
  File "/tmp/cpython/Lib/test/libregrtest/main.py", line 389, in main
    self.display_result()
  File "/tmp/cpython/Lib/test/libregrtest/main.py", line 261, in display_result
    print("%s: %.1fs" % (test, time))
TypeError: a float is required

My suggested fix is to return string describing error as third element of that tuple.

[python-dev]

New changeset 746b98342943 by Victor Stinner in branch 'default':
Close bpo-25373: Fix regrtest --slow with interrupted test
https://hg.python.org/cpython/rev/746b98342943

New changeset ef70e5373131 by Victor Stinner in branch '3.5':
lose bpo-25373: Fix regrtest --slow with interrupted test
https://hg.python.org/cpython/rev/ef70e5373131

[vstinner]

Python 2.7 is not affected by the bug (I'm unable to reproduce it on Python 2.7).

Python 3.4 is near end-of-life and this bug looks like a corner case, I don't think that it's worth to fix it.

I fixed the bug in Python 3.5 and 3.6. I added an unit test for Python 3.6 (test_regrtest). Thanks for the report Arfrever.

[vstinner]

Oh! I didn't see that you proposed a fix, sorry. I fixed the bug differently. IMHO it's easier to not add the test to test_times.

[Arfrever]

Apparently problem was only reproducible in Python 3, because in Python 3, in "while finished < use_mp" loop, accumulate_result() is called early before checking if result[0] is INTERRUPTED or CHILD_ERROR, while in Python 2, accumulate_result() is called after check for result[0].

[Arfrever]

By the way, should "10 slowest tests:\n" (not followed by anything) be printed if all tests failed with CHILD_ERROR or INTERRUPTED?

[vstinner]

No idea. I don't think that --slow is heavily used in the wild. The current
behaiour looks good to me.