classification
Title: Windows: Running the Python test suite sequentially is interrupted by (Pdb) prompt
Type: Stage: resolved
Components: Windows Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Guido.van.Rossum, Mark.Shannon, corona10, gvanrossum, paul.moore, serhiy.storchaka, shihai1991, shreyanavigyan, steve.dower, tim.golden, tim.peters, vstinner, zach.ware
Priority: normal Keywords: patch

Created on 2021-04-27 17:03 by shreyanavigyan, last changed 2021-04-28 15:27 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
tests_log.txt shreyanavigyan, 2021-04-27 17:03 Full Error Log
Pull Requests
URL Status Linked Edit
PR 25675 merged steve.dower, 2021-04-28 00:05
Messages (29)
msg392104 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-27 17:03
Recent test failures have been noticed on Windows 10. The full test log has been attached. The tests test_distutils, test_pdb, test_signal and test_threading require a little bit of attention since there seems to be some kind of error.
msg392109 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-04-27 17:24
I wonder if these four tests do something that affects all threads? The test driver module runs tests in parallel (if you ask it to run all or most tests, like the default).
msg392114 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-27 18:13
Pdb error source - https://github.com/python/cpython/blob/9aea31deddf7458be3546f72185740f3cd06687f/Lib/test/test_pdb.py#L1270

This is where the error in Pdb is originating from.
msg392117 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-27 18:23
The test expects the <built-in default_int_handler> but gets sigint_handler method of a pdb.Pdb instance instead.
msg392118 - (view) Author: Guido van Rossum (Guido.van.Rossum) Date: 2021-04-27 18:37
Can you submit a PR that fixes it?
msg392119 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2021-04-27 18:46
I expect parallelism is a red herring: early in the test output attached to this report:

0:00:04 Run tests sequentially

and there's no other evidence in the output that multiple tests are running simultaneously.

Also on Win10, the 4 failing tests here pass for me if I run them one at a time, so it's not obvious.

I _suspect_ that what's going wrong with test_pdb is the root cause: every now & again, for some weeks now, when I try to run tests on Windows I come back to the cmd.exe window and see that it's just sitting there, waiting at a pdb prompt.

In the output attached to this report, note that after test_threading starts, 

(Pdb) continue
(Pdb) continue
(Pdb) continue
(Pdb) continue

appears out of the blue. But test_pdb is long finished by that time.

But I'm clueless about current pdb internals.
msg392120 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-27 18:55
Yes you're right. Running the failed tests individually does not trigger the errors. And the

(Pdb) continue
(Pdb) continue
(Pdb) continue
(Pdb) continue

actually is manually entered by me. My tests also stop at that prompt but somehow entering these commands again allow us to continue. Why are the errors triggering at all? The tests that are failing when ran alongside the test suite haven't been messed with for a very long time now and still somehow out of the blue they are failing. Any thoughts?
msg392121 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-04-27 19:08
Yes, I also see that pdb prompt. I recommend looking at what different
configurations are used by test.libregrtest.main() when no tests are passed
on the command line.
msg392132 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:03
File "C:\github\cpython\lib\test\test_distutils.py", line 15, in <module>
    import distutils.tests
  File "C:\github\cpython\lib\contextlib.py", line 140, in __exit__
    next(self.gen)
  File "C:\github\cpython\lib\test\support\warnings_helper.py", line 179, in _filterwarnings
    raise AssertionError("filter (%r, %s) did not catch any warning" %
AssertionError: filter ('The distutils package is deprecated', DeprecationWarning) did not catch any warning

Ah, test_distutils fails if distutils was already imported previously. The test should be fixed.

"""
test test_pdb failed -- Traceback (most recent call last):
  File "C:\github\cpython\lib\doctest.py", line 2205, in runTest
    raise self.failureException(self.format_failure(new.getvalue()))
AssertionError: Failed doctest test for test.test_pdb.test_pdb_issue_20766
  File "C:\github\cpython\lib\test\test_pdb.py", line 1270, in test_pdb_issue_20766
"""

This is a surprising failure. No clue why test_pdb fails when other tests are run previously (when tests are run sequentially).

See also bpo-43960
msg392133 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:05
Shreyan Avigyan:
> And the "(Pdb) continue (...) actually is manually entered by me.

Do you mean that you modified the Python source code? Does the issue go away if you revert your change or if you test a newly installed Python?
msg392134 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2021-04-27 21:15
I think the test failures cascade, and some state is not being cleaned up. I'm trying to work through them now, but if someone else is as well, do say so and I'll find something else to do.
msg392135 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2021-04-27 21:16
Shreyan Avigyan:
> And the "(Pdb) continue (...) actually is manually entered by me.

Victor Stinner:
Do you mean that you modified the Python source code?

Me:
Doubt it. For me, with more words: the "(Pdb) " prompt appears all by itself, by magic, and the test run is stuck then. I bet Shreyan meant to say "so I manually entered 'continue [RETURN]' at the pdb prompt to get it unstuck again".

> Does the issue go away if you revert your change or
> if you test a newly installed Python?

For me, I was using Win10 x64 CPython built from yesterday's github master/main.

And thanks for the distutils clue! I bet that one is a distinct issue.

To make it more confusing, all 4 tests passed when I ran with `-j` (to force parallel test execution) - but then test_compileall failed instead :-)
msg392136 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:24
> To make it more confusing, all 4 tests passed when I ran with `-j` (to force parallel test execution) - but then test_compileall failed instead :-)

bpo-37387 "test_compileall fails randomly on Windows when tests are run in parallel" about random PermissionError.
msg392139 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:27
For test_logging test_namer_rotator_inheritance() error: I created bpo-43961 "[Windows] test_logging.test_namer_rotator_inheritance() logs a logging error". It doesn't like like an error and it only happens on Windows.
msg392140 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 21:45
Oh. I also got this surprising (Pdb) prompt when running "python -m test" on Windows.

The prompt doesn't display any output, I only get the prompt display 

(...)
0:34:05 load avg: 1.06 [300/426/2] test_select
0:34:08 load avg: 1.03 [301/426/2] test_selectors
0:34:13 load avg: 0.94 [302/426/2] test_set
0:34:24 load avg: 0.80 [303/426/2] test_setcomps
0:34:26 load avg: 0.78 [304/426/2] test_shelve
0:34:30 load avg: 0.74 [305/426/2] test_shlex
0:34:32 load avg: 0.70 [306/426/2] test_shutil
0:34:36 load avg: 0.66 [307/426/2] test_signal
(Pdb) help
(Pdb) l
(Pdb) ?
(Pdb) help
(Pdb) where
(Pdb) down
(Pdb) p 1
(Pdb) p 2
(Pdb)  


*But* I managed to get more info about that issue:

(Pdb) f=open("debug.txt", "w")
(Pdb) import traceback
(Pdb) traceback.print_stack(file=f)
(Pdb) f.flush()

C:\vstinner\python\master\build\test_python_6260æ\debug.txt content:

(...)
  File "C:\vstinner\python\master\lib\test\libregrtest\runtest.py", line 154, in _runtest
    result = _runtest_inner(ns, test_name,
(...)
  File "C:\vstinner\python\master\lib\unittest\case.py", line 549, in _callTestMethod
    method()
  File "C:\vstinner\python\master\lib\test\test_signal.py", line 1345, in test_sigint
    signal.raise_signal(signal.SIGINT)
  File "C:\vstinner\python\master\lib\unittest\case.py", line 216, in __exit__
    def __exit__(self, exc_type, exc_value, tb):
  File "C:\vstinner\python\master\lib\bdb.py", line 92, in trace_dispatch
    return self.dispatch_call(frame, arg)
  File "C:\vstinner\python\master\lib\bdb.py", line 136, in dispatch_call
    self.user_call(frame, arg)
  File "C:\vstinner\python\master\lib\pdb.py", line 252, in user_call
    self.interaction(frame, None)
  File "C:\vstinner\python\master\lib\pdb.py", line 357, in interaction
    self._cmdloop()
  File "C:\vstinner\python\master\lib\pdb.py", line 322, in _cmdloop
    self.cmdloop()
  File "C:\vstinner\python\master\lib\cmd.py", line 138, in cmdloop
    stop = self.onecmd(line)
  File "C:\vstinner\python\master\lib\pdb.py", line 423, in onecmd
    return cmd.Cmd.onecmd(self, line)
  File "C:\vstinner\python\master\lib\cmd.py", line 216, in onecmd
    return self.default(line)
  File "C:\vstinner\python\master\lib\pdb.py", line 381, in default
    exec(code, globals, locals)
  File "<stdin>", line 1, in <module>


Using debug.txt, I also see that in test_signal, sys.gettrace() = <bound method Bdb.trace_dispatch of <pdb.Pdb object at 0x0000029D85AB3570>>.

Lib/test/libregrtest/save_env.py is supposed to mark a test as "env changed" (ENV_CHANGED) if sys.gettrace() is changed between two tests.
msg392141 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2021-04-27 21:50
Doesn't the pdb prompt use the builtin input()?
msg392149 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 22:59
See also bpo-43963: "test_interpreters has side effects on test_signal".
msg392150 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 23:32
Running these 3 tests is enough to reproduce the issue:
-------------------
vstinner@DESKTOP-DK7VBIL C:\vstinner\python\master>python -m test test_interpreters test_pdb test_threading  
Running Debug|x64 interpreter...
0:00:00 Run tests sequentially
0:00:00 [1/3] test_interpreters
0:00:04 [2/3] test_pdb
test test_pdb failed -- Traceback (most recent call last):
  File "C:\vstinner\python\master\lib\doctest.py", line 2205, in runTest
    raise self.failureException(self.format_failure(new.getvalue()))
AssertionError: Failed doctest test for test.test_pdb.test_pdb_issue_20766
  File "C:\vstinner\python\master\lib\test\test_pdb.py", line 1270, in test_pdb_issue_20766
(...)
0:00:10 load avg: 0.03 [3/3/1] test_threading -- test_pdb failed
(Pdb) 
-------------------

Moreover, my PR 25674 (bpo-43963) fix these tests.
msg392154 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-27 23:40
FYI I used the following patch to debug this issue:

diff --git a/Lib/unittest/case.py b/Lib/unittest/case.py
index 872f121127..ee2e1ff77f 100644
--- a/Lib/unittest/case.py
+++ b/Lib/unittest/case.py
@@ -546,6 +546,8 @@ def _callSetUp(self):
         self.setUp()

     def _callTestMethod(self, method):
+        if sys.gettrace() is not None:
+            raise Exception("sys.gettrace() is not None")
         method()

     def _callTearDown(self):

And I used the following script:
---------------
import random
import os.path
import sys

with open("tests") as fp:
    lines = list(filter(bool, (line.strip() for line in fp)))
print(len(lines))

filename = "test"
loop = 2
while os.path.exists(filename):
    filename = "test%s" % loop
    loop += 1

with open(filename, "w") as fp:
    for _ in range(5):
        test = random.choice(lines)
        print(test, file=fp)
    print("test_signal", file=fp)

with open(filename) as fp:
    for line in fp:
        print(line.rstrip())

args = [sys.executable, "-m", "test", "--fromfile=" + filename]
print("RUN", args)

os.execv(args[0], args)
---------------

I created the "tests" file using the command:

   python -m test --list-tests > tests

Then I removed all tests starting at test_signal, including test_signal. I removed slow tests like asyncio and multiprocessing tests.
msg392164 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-28 06:28
Another issue with the tests is that it has become terribly slow. It's taking about 45 minutes to complete 1 run of the test suite. A few days ago, it took only 10 - 15 minutes. And moreover I think test_threading is also modifying sys.gettrace. The logs have the full error message.

--Snippet--

0:33:17 load avg: 0.80 [307/426/2] test_signal
(Pdb) continue
Warning -- sys.gettrace was modified by test_signal
  Before: None
  After:  <bound method Bdb.trace_dispatch of <pdb.Pdb object at 0x0000021A5D2DCD70>>
test test_signal failed -- Traceback (most recent call last):
  File "C:\github\cpython\lib\test\test_signal.py", line 1345, in test_sigint
    signal.raise_signal(signal.SIGINT)
AssertionError: KeyboardInterrupt not raised

--Snippet--

0:38:22 load avg: 0.04 [353/426/3] test_threading
(Pdb) continue
(Pdb) continue
(Pdb) continue
(Pdb) continue
Warning -- sys.gettrace was modified by test_threading
  Before: None
  After:  <bound method Bdb.trace_dispatch of <pdb.Pdb object at 0x0000021A5D2DCD70>>

--Snippet--
msg392182 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 10:46
Shreyan Avigyan: please try an up to date version of the master branch, I fixed the Pdb issue with commit a09766deab5aff549f40f27080895e148af922ed.
msg392189 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-28 12:17
Same errors. 

(Recompilation was done 1 or 2 hours ago against the then updated master branch. It may not include the latest commit)
msg392190 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-28 12:22
FYI test_signal is no longer modifying sys.gettrace thanks to your fix. But test_threading still does. Do you have a fix for that?
msg392194 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-28 13:19
I ran the test again and test_signal still modifies sys.gettrace()
msg392196 - (view) Author: Shreyan Avigyan (shreyanavigyan) * Date: 2021-04-28 13:44
All the test failures are side effects of other tests because when they are ran individually they do not trigger errors. Running sequentially causes the error.
msg392214 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 15:18
I ran "python -m test" on an up to date master branch (commit fe52eb62191e640e720d184a9a1a04e965b8a062), there is a single remaining issue. test_distutils failed because the deprecation warning was already emited: issue fixed by PR 25675. The other issues are gone.

Shreyan Avigyan: "Same errors."

IMO it's a mistake on your side. You ran an outdated version or you didn't rebuild Python cleanly.

"FYI test_signal is no longer modifying sys.gettrace thanks to your fix. But test_threading still does. (...) I ran the test again and test_signal still modifies sys.gettrace()"

It's not my case on my machine, again it sounds like an issue on your side.
msg392216 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 15:20
> Another issue with the tests is that it has become terribly slow. It's taking about 45 minutes to complete 1 run of the test suite. A few days ago, it took only 10 - 15 minutes.

It took 49 minutes on my Windows 10 VM. Are you sure that you ran the test suite sequentially when it was slower?

I advice you run using -j0 option to run tests in parallel: it's much faster, and it's also more reliable.

== Tests result: FAILURE ==

384 tests OK.

1 test failed:
    test_distutils

41 tests skipped:
    test_curses test_dbm_gnu test_dbm_ndbm test_devpoll test_epoll
    test_fcntl test_fork1 test_gdb test_grp test_ioctl test_kqueue
    test_multiprocessing_fork test_multiprocessing_forkserver test_nis
    test_openpty test_ossaudiodev test_pipes test_poll test_posix
    test_pty test_pwd test_readline test_resource test_smtpnet
    test_socketserver test_spwd test_syslog test_threadsignals
    test_timeout test_tix test_tk test_ttk_guionly test_urllib2net
    test_urllibnet test_wait3 test_wait4 test_winsound test_xmlrpc_net
    test_xxlimited test_xxtestfuzz test_zipfile64

Total duration: 49 min 12 sec
Tests result: FAILURE
msg392218 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2021-04-28 15:21
New changeset c1a9535989cc7323099725503519a17f79d083f5 by Steve Dower in branch 'master':
bpo-43955: Handle the case where the distutils warning has already been triggered (GH-25675)
https://github.com/python/cpython/commit/c1a9535989cc7323099725503519a17f79d083f5
msg392219 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-04-28 15:27
Thanks everyone for fixing these issues and thanks Shreyan for the bug report.

The main initial is now fixed, so I close the issue.

Let's continue the discussions in remaining open issues:

* bpo-37387: test_compileall fails randomly on Windows when tests are run in parallel
* bpo-43960: test_pdb fails when only some tests are run
* bpo-43961 [Windows] test_logging.test_namer_rotator_inheritance() logs a logging error
History
Date User Action Args
2021-04-28 15:27:25vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg392219

stage: patch review -> resolved
2021-04-28 15:21:58steve.dowersetmessages: + msg392218
2021-04-28 15:20:25vstinnersetmessages: + msg392216
2021-04-28 15:18:52vstinnersetmessages: + msg392214
2021-04-28 13:44:54shreyanavigyansetmessages: + msg392196
2021-04-28 13:19:44shreyanavigyansetmessages: + msg392194
2021-04-28 12:22:06shreyanavigyansetmessages: + msg392190
2021-04-28 12:17:01shreyanavigyansetmessages: + msg392189
2021-04-28 10:46:24vstinnersetmessages: + msg392182
2021-04-28 06:28:51shreyanavigyansetmessages: + msg392164
2021-04-28 00:05:17steve.dowersetkeywords: + patch
stage: patch review
pull_requests: + pull_request24366
2021-04-27 23:40:30vstinnersetmessages: + msg392154
2021-04-27 23:32:24vstinnersetmessages: + msg392150
2021-04-27 22:59:33vstinnersetmessages: + msg392149
2021-04-27 22:30:03vstinnersettitle: Test Failures on Windows 10 -> Windows: Running the Python test suite sequentially is interrupted by (Pdb) prompt
2021-04-27 21:50:25gvanrossumsetmessages: + msg392141
2021-04-27 21:45:37vstinnersetmessages: + msg392140
2021-04-27 21:27:34vstinnersetmessages: + msg392139
2021-04-27 21:24:57vstinnersetmessages: + msg392136
2021-04-27 21:16:06tim.peterssetmessages: + msg392135
2021-04-27 21:15:39steve.dowersetmessages: + msg392134
2021-04-27 21:05:44vstinnersetmessages: + msg392133
2021-04-27 21:03:15vstinnersetmessages: + msg392132
2021-04-27 19:08:44gvanrossumsetmessages: + msg392121
2021-04-27 18:55:51shreyanavigyansetmessages: + msg392120
2021-04-27 18:47:00tim.peterssetnosy: + tim.peters
messages: + msg392119
2021-04-27 18:37:18Guido.van.Rossumsetmessages: + msg392118
2021-04-27 18:23:05shreyanavigyansetmessages: + msg392117
2021-04-27 18:13:55shreyanavigyansetmessages: + msg392114
2021-04-27 17:24:57gvanrossumsetmessages: + msg392109
2021-04-27 17:14:36pablogsalsetnosy: - pablogsal
2021-04-27 17:07:31christian.heimessetnosy: - christian.heimes
2021-04-27 17:04:33erlendaaslandsetnosy: - erlendaasland
2021-04-27 17:03:07shreyanavigyancreate