test_ftplib fails with "env changed" if a socket operation times out in a thread (in the "dummy FTP server").

Example on AMD64 Fedora Rawhide LTO 3.10:
https://buildbot.python.org/all/#/builders/653/builds/95

0:02:41 load avg: 8.20 [394/427/1] test_ftplib failed (env changed) -- running: test_lib2to3 (33.9 sec), test_peg_generator (2 min 37 sec), test_concurrent_futures (1 min 53 sec), test_gdb (1 min 37 sec)
Warning -- Uncaught thread exception: Exception
Exception in thread Thread-34:
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asyncore.py", line 420, in handle_read_event
    self.handle_read()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asynchat.py", line 171, in handle_read
    self.found_terminator()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/test/test_ftplib.py", line 129, in found_terminator
    method(arg)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/test/test_ftplib.py", line 154, in cmd_pasv
    conn, addr = sock.accept()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/socket.py", line 293, in accept
    fd, addr = self._accept()
TimeoutError: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/threading.py", line 1006, in _bootstrap_inner
    self.run()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/test/test_ftplib.py", line 292, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asyncore.py", line 207, in loop
    poll_fun(timeout, map)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asyncore.py", line 150, in poll
    read(obj)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/asyncore.py", line 87, in read
    obj.handle_error()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-rawhide-x86_64.lto/build/Lib/test/test_ftplib.py", line 134, in handle_error
    raise Exception
Exception

test_abort (test.test_ftplib.TestFTPClass) ... ok
(...)
test__all__ (test.test_ftplib.MiscTestCase) ... ok

----------------------------------------------------------------------

Ran 94 tests in 8.491s

OK (skipped=2)



A similar issue (is it the same one?) can be reproduced with attached test_ftplib_timeout.patch which sets the timeout to 1 nanosecond and the command:

$ ./python -m test test_ftplib -v --fail-env-changed -m test.test_ftplib.TestFTPClass.test_retrlines
== CPython 3.11.0a0 (heads/main:257e400a19, Jun 8 2021, 18:04:17) [GCC 11.1.1 20210531 (Red Hat 11.1.1-3)]
== Linux-5.12.8-300.fc34.x86_64-x86_64-with-glibc2.33 little-endian
== cwd: /home/vstinner/python/main/build/test_python_129053æ
== CPU count: 8
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 1.03 Run tests sequentially
0:00:00 load avg: 1.03 [1/1] test_ftplib
test_retrlines (test.test_ftplib.TestFTPClass) ... Warning -- Uncaught thread exception: Exception
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/home/vstinner/python/main/Lib/asyncore.py", line 420, in handle_read_event
    self.handle_read()
  File "/home/vstinner/python/main/Lib/asynchat.py", line 171, in handle_read
    self.found_terminator()
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 129, in found_terminator
    method(arg)
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 154, in cmd_pasv
    conn, addr = sock.accept()
  File "/home/vstinner/python/main/Lib/socket.py", line 293, in accept
    fd, addr = self._accept()
TimeoutError: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/threading.py", line 1006, in _bootstrap_inner
    self.run()
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 292, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/vstinner/python/main/Lib/asyncore.py", line 207, in loop
    poll_fun(timeout, map)
  File "/home/vstinner/python/main/Lib/asyncore.py", line 150, in poll
    read(obj)
  File "/home/vstinner/python/main/Lib/asyncore.py", line 87, in read
    obj.handle_error()
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 134, in handle_error
    raise Exception
Exception
ERROR

======================================================================
ERROR: test_retrlines (test.test_ftplib.TestFTPClass)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 598, in test_retrlines
    self.client.retrlines('retr', received.append)
  File "/home/vstinner/python/main/Lib/ftplib.py", line 462, in retrlines
    with self.transfercmd(cmd) as conn, \
  File "/home/vstinner/python/main/Lib/ftplib.py", line 393, in transfercmd
    return self.ntransfercmd(cmd, rest)[0]
  File "/home/vstinner/python/main/Lib/ftplib.py", line 354, in ntransfercmd
    conn = socket.create_connection((host, port), self.timeout,
  File "/home/vstinner/python/main/Lib/socket.py", line 844, in create_connection
    raise err
  File "/home/vstinner/python/main/Lib/socket.py", line 832, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused

----------------------------------------------------------------------

Ran 1 test in 0.021s

FAILED (errors=1)
test test_ftplib failed
test_ftplib failed

== Tests result: FAILURE ==

1 test failed:
    test_ftplib

Total duration: 169 ms
Tests result: FAILURE

Another example on PPC64LE Fedora Stable LTO 3.10:
https://buildbot.python.org/all/#/builders/644/builds/98

0:00:38 load avg: 7.51 [ 78/427/1] test_ftplib failed (env changed) -- running: test_signal (39.0 sec), test_nntplib (35.2 sec)
Warning -- Uncaught thread exception: Exception
Exception in thread Thread-34:
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asyncore.py", line 420, in handle_read_event
    self.handle_read()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asynchat.py", line 171, in handle_read
    self.found_terminator()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/test/test_ftplib.py", line 129, in found_terminator
    method(arg)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/test/test_ftplib.py", line 154, in cmd_pasv
    conn, addr = sock.accept()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/socket.py", line 293, in accept
    fd, addr = self._accept()
TimeoutError: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/threading.py", line 1006, in _bootstrap_inner
    self.run()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/test/test_ftplib.py", line 292, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asyncore.py", line 207, in loop
    poll_fun(timeout, map)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asyncore.py", line 150, in poll
    read(obj)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/asyncore.py", line 87, in read
    obj.handle_error()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-ppc64le.lto/build/Lib/test/test_ftplib.py", line 134, in handle_error
    raise Exception
Exception

aarch64 Fedora Stable Clang 3.10:
https://buildbot.python.org/all/#/builders/635/builds/253

0:00:23 load avg: 12.40 [404/427/1] test_ftplib failed (env changed)
Warning -- Uncaught thread exception: Exception
Exception in thread Thread-34:
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asyncore.py", line 90, in read
    obj.handle_read_event()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asyncore.py", line 427, in handle_read_event
    self.handle_read()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asynchat.py", line 179, in handle_read
    self.found_terminator()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/test/test_ftplib.py", line 134, in found_terminator
    method(arg)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/test/test_ftplib.py", line 159, in cmd_pasv
    conn, addr = sock.accept()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/socket.py", line 293, in accept
    fd, addr = self._accept()
TimeoutError: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/threading.py", line 1009, in _bootstrap_inner
    self.run()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/test/test_ftplib.py", line 297, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asyncore.py", line 157, in poll
    read(obj)
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/asyncore.py", line 94, in read
    obj.handle_error()
  File "/home/buildbot/buildarea/3.10.cstratak-fedora-stable-aarch64.clang/build/Lib/test/test_ftplib.py", line 139, in handle_error
    raise Exception
Exception

This failure in required Ubuntu test is blocking me from merging a totally unrelated change in IDLE.  PR-28228.  Please disable the phony failing test.

Another error on AMD64 Fedora Rawhide LTO + PGO 3.x:
https://buildbot.python.org/all/#/builders/79/builds/870

0:01:10 load avg: 4.48 [236/427/1] test_ftplib failed (env changed) -- running: (...)
Warning -- Uncaught thread exception: Exception
Exception in thread Thread-67:
Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/asyncore.py", line 90, in read
    obj.handle_read_event()
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/test/test_ftplib.py", line 384, in handle_read_event
    self._do_ssl_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/test/test_ftplib.py", line 345, in _do_ssl_handshake
    self.socket.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/ssl.py", line 1346, in do_handshake
    self._sslobj.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:998)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/threading.py", line 1031, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/test/test_ftplib.py", line 298, in run
    asyncore.loop(timeout=0.1, count=1)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/asyncore.py", line 157, in poll
    read(obj)
    ^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/asyncore.py", line 94, in read
    obj.handle_error()
    ^^^^^^^^^^^^^^^^^^
  File "/home/buildbot/buildarea/3.x.cstratak-fedora-rawhide-x86_64.lto-pgo/build/Lib/test/test_ftplib.py", line 421, in handle_error
    raise Exception
    ^^^^^^^^^^^^^^^
Exception

I reproduced manually the issue. test_makeport() can trigger the "Uncaught thread exception: Exception".

test_makeport (test.test_ftplib.TestTLS_FTPClassMixin) ...

Warning -- Uncaught thread exception: Exception
Exception in thread Thread-67:
Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/asyncore.py", line 90, in read
    obj.handle_read_event()
    ^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 384, in handle_read_event
    self._do_ssl_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 345, in _do_ssl_handshake
    self.socket.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/ssl.py", line 1346, in do_handshake
    self._sslobj.do_handshake()
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:998)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/python/main/Lib/threading.py", line 1031, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 298, in run
    asyncore.loop(timeout=0.1, count=1)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/asyncore.py", line 214, in loop
    poll_fun(timeout, map)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/asyncore.py", line 157, in poll
    read(obj)
    ^^^^^^^^^
  File "/home/vstinner/python/main/Lib/asyncore.py", line 94, in read
    obj.handle_error()
    ^^^^^^^^^^^^^^^^^^
  File "/home/vstinner/python/main/Lib/test/test_ftplib.py", line 421, in handle_error
    raise Exception
    ^^^^^^^^^^^^^^^
Exception

ok

Maybe it's time to actually try to fix this test rather than just complaining about it? Surely *somebody* here has an idea? Else maybe we need to just disable it.

On Fedora Rawhide x64-64, I can reproduce the test_ftplib test_makeport() issue in reliable way.

On Python 3.9, the test also logs the exception but the test is marked as a success:
---
$ ./python -m test -u all test_ftplib -v -m test_makeport
(...)
test_makeport (test.test_ftplib.TestFTPClass) ... ok
test_makeport (test.test_ftplib.TestIPv6Environment) ... ok
test_makeport (test.test_ftplib.TestTLS_FTPClassMixin) ... Exception in thread Thread-3:
Traceback (most recent call last):
  File "/home/vstinner/python/3.9/Lib/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/home/vstinner/python/3.9/Lib/test/test_ftplib.py", line 377, in handle_read_event
    self._do_ssl_handshake()
  File "/home/vstinner/python/3.9/Lib/test/test_ftplib.py", line 338, in _do_ssl_handshake
    self.socket.do_handshake()
  File "/home/vstinner/python/3.9/Lib/ssl.py", line 1309, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLZeroReturnError: TLS/SSL connection has been closed (EOF) (_ssl.c:1129)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/vstinner/python/3.9/Lib/threading.py", line 973, in _bootstrap_inner
    self.run()
  File "/home/vstinner/python/3.9/Lib/test/test_ftplib.py", line 291, in run
    asyncore.loop(timeout=0.1, count=1)
  File "/home/vstinner/python/3.9/Lib/asyncore.py", line 207, in loop
    poll_fun(timeout, map)
  File "/home/vstinner/python/3.9/Lib/asyncore.py", line 150, in poll
    read(obj)
  File "/home/vstinner/python/3.9/Lib/asyncore.py", line 87, in read
    obj.handle_error()
  File "/home/vstinner/python/3.9/Lib/test/test_ftplib.py", line 414, in handle_error
    raise Exception
Exception
ok
(...)
Tests result: SUCCESS
---

make buildbottest uses -W option which hides the test output unless the test failed.

In this case, the unhandled threading exception is siently ignored:
---
$ ./python -m test -u all test_ftplib -W -m test_makeport -j1
(...)
0:00:00 load avg: 0.75 [1/1] test_ftplib passed
(...)
Tests result: SUCCESS
---

On Python 3.10 and newer, libregrtest sets a threading excepthook to (1) log the exception (2) mark that the note "altered the environmen": mark the test as "ENV CHANGED". I did that to detect unhandled exceptions like this one.

In this case, unhandled exceptions come from the four handle_error() method of test_ftplib dispatcher classes, like SSLConnection, which are implemented as:

    def handle_error(self):
        raise Exception

test_ftplib closes sockets in TestFTPClass.tearDown() method:

    def tearDown(self):
        self.client.close()
        self.server.stop()
        # Explicitly clear the attribute to prevent dangling thread
        self.server = None
        asyncore.close_all(ignore_all=True)

The problem is that the code doesn't implement any kind of error handling. If asyncore gets a socket exception, it calls handle_error() which raises an a new Exception instance. That's it.

IMO it's not worth it to bother with handling socket errors in test_ftplib. The server is implemented with asyncore which is deprecated since Python 3.6. The FTP protocol itself is legacy.

Attached PR simply ignores socket erors rather than logging unhandled threading exceptions.

GH-31069 simply silently ignore all socket errors.

I tried to write a smart fix which only ignores socket errors when tests are done, in tearDown(). But than I got issues in makepasv() tests which creates a socket and immediately closes it. The server also logs an error in this case.

IMO it's not worth it trying to write the perfect error handling for test_ftplib.

New changeset 0611eafc709cbe8a2a0bdde082d25df0c5034de7 by Victor Stinner in branch 'main':
bpo-44359: Fix test_ftplib unhandled thread exceptions (GH-31069)
https://github.com/python/cpython/commit/0611eafc709cbe8a2a0bdde082d25df0c5034de7

New changeset 85b421fbff23ff41c52fa5bde191920b3701f0d0 by Miss Islington (bot) in branch '3.10':
bpo-44359: Fix test_ftplib unhandled thread exceptions (GH-31069)
https://github.com/python/cpython/commit/85b421fbff23ff41c52fa5bde191920b3701f0d0

New changeset 0371e5d7f1248abb0712fc98c3135d01d265cec8 by Miss Islington (bot) in branch '3.9':
bpo-44359: Fix test_ftplib unhandled thread exceptions (GH-31069)
https://github.com/python/cpython/commit/0371e5d7f1248abb0712fc98c3135d01d265cec8