classification
Title: test_ftplib fails as "env changes" if a socket operation times out in a thread: TimeoutError is not catched
Type: Stage: patch review
Components: Tests Versions: Python 3.11, Python 3.10
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: corona10, erlendaasland, giovanniwijaya, lukasz.langa, orsenthil, shihai1991, terry.reedy, vstinner
Priority: normal Keywords: patch

Created on 2021-06-09 07:58 by vstinner, last changed 2021-09-10 20:47 by giovanniwijaya.

Files
File name Uploaded Description Edit
test_ftplib_timeout.patch vstinner, 2021-06-09 07:58
Pull Requests
URL Status Linked Edit
PR 28228 giovanniwijaya, 2021-09-10 20:47
Messages (4)
msg395389 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-06-09 07:58
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
msg395627 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-06-11 09:44
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
msg400735 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-08-31 14:00
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
msg401614 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2021-09-10 20:29
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.
History
Date User Action Args
2021-09-10 20:47:46giovanniwijayasetnosy: + giovanniwijaya

pull_requests: + pull_request26699
stage: patch review
2021-09-10 20:29:03terry.reedysetnosy: + terry.reedy, lukasz.langa
messages: + msg401614
2021-09-01 00:01:53shihai1991setnosy: + shihai1991
2021-08-31 14:00:15vstinnersetmessages: + msg400735
2021-06-12 13:14:36corona10setnosy: + corona10
2021-06-11 10:47:33orsenthilsetnosy: + orsenthil
2021-06-11 09:44:09vstinnersetmessages: + msg395627
2021-06-09 08:02:51erlendaaslandsetnosy: + erlendaasland
2021-06-09 07:58:31vstinnercreate