-
-
Notifications
You must be signed in to change notification settings - Fork 31.1k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
test_ftplib.test_makeport() fails as "env changes" if a socket operation times out in a thread: TimeoutError is not catched #88525
Comments
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: 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 ---------------------------------------------------------------------- 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 ====================================================================== 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) == Tests result: FAILURE == 1 test failed: Total duration: 169 ms |
Another example on PPC64LE Fedora Stable LTO 3.10: 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: 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: 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. |
#75252 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. |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: