classification
Title: test.regrtest: -jN (with N != 1) + --slow + child error or interruption = TypeError
Type: Stage: resolved
Components: Tests Versions: Python 3.6, Python 3.4, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Arfrever, python-dev, vstinner
Priority: normal Keywords: patch

Created on 2015-10-11 04:34 by Arfrever, last changed 2015-10-11 20:09 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
regrtest-2.7.patch Arfrever, 2015-10-11 04:36 Patch for 2.7
regrtest-3.4.patch Arfrever, 2015-10-11 04:36 Patch for 3.4
regrtest-3.5.patch Arfrever, 2015-10-11 04:37 Patch for 3.5
regrtest-3.6.patch Arfrever, 2015-10-11 04:37 Patch for 3.6
Messages (7)
msg252757 - (view) Author: Arfrever Frehtes Taifersar Arahesis (Arfrever) * (Python triager) Date: 2015-10-11 04:34
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.
msg252781 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2015-10-11 08:41
New changeset 746b98342943 by Victor Stinner in branch 'default':
Close #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 #25373: Fix regrtest --slow with interrupted test
https://hg.python.org/cpython/rev/ef70e5373131
msg252783 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-11 08:44
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.
msg252784 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-11 08:46
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.
msg252793 - (view) Author: Arfrever Frehtes Taifersar Arahesis (Arfrever) * (Python triager) Date: 2015-10-11 09:10
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].
msg252795 - (view) Author: Arfrever Frehtes Taifersar Arahesis (Arfrever) * (Python triager) Date: 2015-10-11 09:28
By the way, should "10 slowest tests:\n" (not followed by anything) be printed if all tests failed with CHILD_ERROR or INTERRUPTED?
msg252823 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-10-11 20:09
No idea. I don't think that --slow is heavily used in the wild. The current
behaiour looks good to me.
History
Date User Action Args
2015-10-11 20:09:20vstinnersetmessages: + msg252823
2015-10-11 09:28:36Arfreversetmessages: + msg252795
2015-10-11 09:10:00Arfreversetmessages: + msg252793
2015-10-11 08:46:13vstinnersetmessages: + msg252784
2015-10-11 08:44:40vstinnersetmessages: + msg252783
versions: - Python 2.7
2015-10-11 08:41:14python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg252781

resolution: fixed
stage: resolved
2015-10-11 04:37:30Arfreversetfiles: + regrtest-3.6.patch
2015-10-11 04:37:15Arfreversetfiles: + regrtest-3.5.patch
2015-10-11 04:36:58Arfreversetfiles: + regrtest-3.4.patch
2015-10-11 04:36:35Arfreversetfiles: + regrtest-2.7.patch
keywords: + patch
2015-10-11 04:34:50Arfrevercreate