mitogen
mitogen copied to clipboard
mitogen-hq
test_success (tests.connection_test.FetchFileTest) leaked FDs. Count before: 6, after: 7
I am seeing this interittantly when I run the tests suites on Ubuntu 20.04, under tox
:~/src/mitogen master(+120/-30)+* 1± tox -r -e py36-mode_ansible-ansible29
GLOB sdist-make: /home/alex/src/mitogen/setup.py
py36-mode_ansible-ansible29 recreate: /home/alex/src/mitogen/.tox/py36-mode_ansible-ansible29
py36-mode_ansible-ansible29 inst: /home/alex/src/mitogen/.tox/.tmp/package/1/mitogen-0.2.9.zip
py36-mode_ansible-ansible29 installed: appdirs==1.4.3,CacheControl==0.12.6,certifi==2019.11.28,chardet==3.0.4,colorama==0.4.3,contextlib2==0.6.0,distlib==0.3.0,distro==1.4.0,html5lib==1.0.1,idna==2.8,ipaddr==2.2.0,lockfile==0.12.2,mitogen==0.2.9,msgpack==0.6.2,packaging==20.3,pep517==0.8.2,progress==1.5,pyparsing==2.4.6,pytoml==0.1.21,requests==2.22.0,retrying==1.3.3,six==1.14.0,urllib3==1.25.8,webencodings==0.5.1
py36-mode_ansible-ansible29 run-test-pre: PYTHONHASHSEED='1656202831'
py36-mode_ansible-ansible29 run-test-pre: commands[0] | /home/alex/src/mitogen/.ci/ansible_install.py
+ pip install pycparser<2.19 idna<2.7
+ docker pull mitogen/debian-test
+ docker pull mitogen/centos6-test
+ docker pull mitogen/centos7-test
Using default tag: latest
Using default tag: latest
Using default tag: latest
Processing /home/alex/.cache/pip/wheels/be/ba/89/4df1a952bcd0716ac1d5f6f051233e1f3a653948f08bc0a7be/pycparser-2.18-py2.py3-none-any.whl
Collecting idna<2.7
Using cached idna-2.6-py2.py3-none-any.whl (56 kB)
Installing collected packages: pycparser, idna
Attempting uninstall: idna
Found existing installation: idna 2.8
Uninstalling idna-2.8:
Successfully uninstalled idna-2.8
Successfully installed idna-2.6 pycparser-2.18
+ pip install -r tests/requirements.txt -r tests/ansible/requirements.txt
latest: Pulling from mitogen/centos7-test
Digest: sha256:6f95156ee69b40b4a5e636c6ec225a8f9dcee830d19c2a2cbe7f66e6a11f4c2e
Status: Image is up to date for mitogen/centos7-test:latest
docker.io/mitogen/centos7-test:latest
latest: Pulling from mitogen/debian-test
Digest: sha256:0be06d13060a9b234fb822077d9a01358bc9fd06da9c80b742cfb9bad91bcbc8
Status: Image is up to date for mitogen/debian-test:latest
docker.io/mitogen/debian-test:latest
latest: Pulling from mitogen/centos6-test
Digest: sha256:25e5c5646d61eba042f5520e9cc0054c61b8008d0116bacb483ebe640bcc4831
Status: Image is up to date for mitogen/centos6-test:latest
docker.io/mitogen/centos6-test:latest
Ignoring faulthandler: markers 'python_version < "3.3"' don't match your environment
Ignoring urllib3: markers 'python_version < "2.7.9"' don't match your environment
Ignoring idna: markers 'python_version < "2.7"' don't match your environment
Ignoring PyYAML: markers 'python_version < "2.7"' don't match your environment
Processing /home/alex/.cache/pip/wheels/34/38/9a/39028cefc7b8324d53649916acff87936d908b60e58acbda4c/psutil-5.4.8-cp36-cp36m-linux_x86_64.whl
Collecting coverage==4.5.1
Using cached coverage-4.5.1-cp36-cp36m-manylinux1_x86_64.whl (202 kB)
Collecting Django==1.6.11
Using cached Django-1.6.11-py2.py3-none-any.whl (6.7 MB)
Collecting mock==2.0.0
Using cached mock-2.0.0-py2.py3-none-any.whl (56 kB)
Collecting pytz==2018.5
Using cached pytz-2018.5-py2.py3-none-any.whl (510 kB)
Collecting cffi==1.11.2
Using cached cffi-1.11.2-cp36-cp36m-manylinux1_x86_64.whl (419 kB)
Requirement already satisfied: pycparser==2.18 in ./.tox/py36-mode_ansible-ansible29/lib/python3.6/site-packages (from -r tests/requirements.txt (line 7)) (2.18)
Collecting pytest-catchlog==1.2.2
Using cached pytest_catchlog-1.2.2-py2.py3-none-any.whl (10 kB)
Collecting pytest==3.1.2
Using cached pytest-3.1.2-py2.py3-none-any.whl (180 kB)
Processing /home/alex/.cache/pip/wheels/6d/b1/d6/d38318cbb21636c2e5bed1b6307a332993fd53f41821629e06/timeoutcontext-1.2.0-py2.py3-none-any.whl
Collecting unittest2==1.1.0
Using cached unittest2-1.1.0-py2.py3-none-any.whl (96 kB)
Collecting pyOpenSSL<20.0.0
Using cached pyOpenSSL-19.1.0-py2.py3-none-any.whl (53 kB)
Collecting paramiko==2.3.2
Using cached paramiko-2.3.2-py2.py3-none-any.whl (194 kB)
Processing /home/alex/.cache/pip/wheels/40/da/b9/e14314e18b9c71fb246d5cd7dfacab04e0ade8e6825bc7e314/hdrhistogram-0.6.1-cp36-cp36m-linux_x86_64.whl
Processing /home/alex/.cache/pip/wheels/ab/80/60/97eaebe423482bcf0963b19495b4cfe6c4caef59761a0c427d/PyYAML-3.13-cp36-cp36m-linux_x86_64.whl
Requirement already satisfied: six>=1.9 in ./.tox/py36-mode_ansible-ansible29/lib/python3.6/site-packages (from mock==2.0.0->-r tests/requirements.txt (line 4)) (1.14.0)
Collecting pbr>=0.11
Using cached pbr-5.5.1-py2.py3-none-any.whl (106 kB)
Collecting py>=1.1.1
Using cached py-1.9.0-py2.py3-none-any.whl (99 kB)
Requirement already satisfied: setuptools in ./.tox/py36-mode_ansible-ansible29/lib/python3.6/site-packages (from pytest==3.1.2->-r tests/requirements.txt (line 10)) (44.0.0)
Collecting traceback2
Using cached traceback2-1.4.0-py2.py3-none-any.whl (16 kB)
Collecting argparse
Using cached argparse-1.4.0-py2.py3-none-any.whl (23 kB)
Collecting cryptography>=2.8
Using cached cryptography-3.2.1-cp35-abi3-manylinux2010_x86_64.whl (2.6 MB)
Collecting bcrypt>=3.1.3
Using cached bcrypt-3.2.0-cp36-abi3-manylinux2010_x86_64.whl (63 kB)
Collecting pynacl>=1.0.1
Using cached PyNaCl-1.4.0-cp35-abi3-manylinux1_x86_64.whl (961 kB)
Collecting pyasn1>=0.1.7
Using cached pyasn1-0.4.8-py2.py3-none-any.whl (77 kB)
Processing /home/alex/.cache/pip/wheels/6e/9c/ed/4499c9865ac1002697793e0ae05ba6be33553d098f3347fb94/future-0.18.2-py3-none-any.whl
Collecting linecache2
Using cached linecache2-1.0.0-py2.py3-none-any.whl (12 kB)
Installing collected packages: psutil, coverage, Django, pbr, mock, pytz, cffi, py, pytest, pytest-catchlog, timeoutcontext, linecache2, traceback2, argparse, unittest2, cryptography, pyOpenSSL, bcrypt, pynacl, pyasn1, paramiko, future, hdrhistogram, PyYAML
Successfully installed Django-1.6.11 PyYAML-3.13 argparse-1.4.0 bcrypt-3.2.0 cffi-1.11.2 coverage-4.5.1 cryptography-3.2.1 future-0.18.2 hdrhistogram-0.6.1 linecache2-1.0.0 mock-2.0.0 paramiko-2.3.2 pbr-5.5.1 psutil-5.4.8 py-1.9.0 pyOpenSSL-19.1.0 pyasn1-0.4.8 pynacl-1.4.0 pytest-3.1.2 pytest-catchlog-1.2.2 pytz-2018.5 timeoutcontext-1.2.0 traceback2-1.4.0 unittest2-1.1.0
+ pip install -q ansible==2.9.6
py36-mode_ansible-ansible29 run-test: commands[0] | /home/alex/src/mitogen/.ci/ansible_tests.py
travis_fold:start:unit_tests
Running: ['/usr/bin/time', '--', './run_tests', '-v']
----- ulimits -----
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 31114
max locked memory (kbytes, -l) 65536
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 31114
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
-------------------
test_assign_controller_1core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_controller_2core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_controller_3core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_controller_4core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_muxprocess_1core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_muxprocess_2core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_muxprocess_3core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_muxprocess_4core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_subprocess_1core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_subprocess_2core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_subprocess_3core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_subprocess_4core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_worker_1core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_worker_2core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_worker_3core (tests.affinity_test.FixedPolicyTest) ... ok
test_assign_worker_4core (tests.affinity_test.FixedPolicyTest) ... ok
test_clear_on_popen (tests.affinity_test.LinuxPolicyTest) ... ok
test_set_cpu_mask (tests.affinity_test.LinuxPolicyTest) ... ok
test_high_cpus (tests.affinity_test.MockLinuxPolicyTest) ... skipped 'select.select() not supported'
test_success (tests.connection_test.FetchFileTest) ... COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
gnome-ter 7024 alex 17u CHR 5,2 0t0 89 /dev/ptmx ->/dev/pts/2 178124,bash,0u 178124,bash,1u 178124,bash,2u 178124,bash,255u 291623,ansible-p,0u 291623,ansible-p,1u 291623,ansible-p,2u 291661,ansible-p,0u 291661,ansible-p,1u 291661,ansible-p,2u 291661,ansible-p,7u 292424,ansible-p,0u 292424,ansible-p,1u 292424,ansible-p,2u 292462,ansible-p,0u 292462,ansible-p,1u 292462,ansible-p,2u 292462,ansible-p,7u 293592,ansible-p,0u 293592,ansible-p,1u 293592,ansible-p,2u 293630,ansible-p,0u 293630,ansible-p,1u 293630,ansible-p,2u 293630,ansible-p,7u 294647,ansible-p,0u 294647,ansible-p,1u 294647,ansible-p,2u 294685,ansible-p,0u 294685,ansible-p,1u 294685,ansible-p,2u 294685,ansible-p,7u 295814,ansible-p,0u 295814,ansible-p,1u 295814,ansible-p,2u 295852,ansible-p,0u 295852,ansible-p,1u 295852,ansible-p,2u 295852,ansible-p,7u 399775,ansible-p,0u 399775,ansible-p,1u 399775,ansible-p,2u 399813,ansible-p,0u 399813,ansible-p,1u 399813,ansible-p,2u 399813,ansible-p,7u 1264319,tox,0u 1264319,tox,1u 1264319,tox,2u 1264568,python,0u 1264568,python,1u 1264568,python,2u 1264570,time,0u 1264570,time,1u 1264570,time,2u 1264571,bash,0u 1264571,bash,1u 1264571,bash,2u 1264574,coverage,0u 1264574,coverage,1u 1264574,coverage,2u 1264579,coverage,0u 1264579,coverage,1u 1264579,coverage,2u 1264615,python,7u 1264618,python,7u 1264622,sh,0u 1264622,sh,1u 1264622,sh,2u 1264623,lsof,0u 1264623,lsof,2u 1264624,grep,1u 1264624,grep,2u
coverage 1264574 alex cwd DIR 8,3 4096 1839561 /home/alex/src/mitogen
coverage 1264574 alex rtd DIR 8,3 4096 2 /
coverage 1264574 alex txt REG 8,3 4502648 3151912 /usr/bin/python3.6
coverage 1264574 alex DEL REG 0,1 16879174 /dev/zero
coverage 1264574 alex DEL REG 0,1 16887114 /dev/zero
coverage 1264574 alex DEL REG 0,28 185 /dev/shm/A6Uhfo
coverage 1264574 alex DEL REG 0,28 183 /dev/shm/wcY7Jm
coverage 1264574 alex DEL REG 0,28 182 /dev/shm/t1jPqm
coverage 1264574 alex DEL REG 0,28 179 /dev/shm/0sx68m
coverage 1264574 alex DEL REG 0,28 175 /dev/shm/4ySefo
coverage 1264574 alex DEL REG 0,28 171 /dev/shm/MwUF3k
coverage 1264574 alex DEL REG 0,28 165 /dev/shm/aszIfk
coverage 1264574 alex DEL REG 0,28 156 /dev/shm/JlSYco
coverage 1264574 alex DEL REG 0,28 148 /dev/shm/bKGNIj
coverage 1264574 alex DEL REG 0,28 145 /dev/shm/ENjJkl
coverage 1264574 alex DEL REG 0,28 143 /dev/shm/WyQRMn
coverage 1264574 alex DEL REG 0,28 141 /dev/shm/EpXOHm
coverage 1264574 alex DEL REG 0,28 140 /dev/shm/gphkgo
coverage 1264574 alex DEL REG 0,28 137 /dev/shm/sRF5ik
coverage 1264574 alex DEL REG 0,28 128 /dev/shm/f31ULl
coverage 1264574 alex DEL REG 0,28 122 /dev/shm/ErZRdl
coverage 1264574 alex DEL REG 0,28 102 /dev/shm/yzDzPj
coverage 1264574 alex DEL REG 0,28 100 /dev/shm/vL6Cxm
coverage 1264574 alex DEL REG 0,28 96 /dev/shm/PoeUfn
coverage 1264574 alex DEL REG 0,28 86 /dev/shm/bZEcVj
coverage 1264574 alex DEL REG 0,28 77 /dev/shm/NZaCpm
coverage 1264574 alex DEL REG 0,28 74 /dev/shm/qAgEVk
coverage 1264574 alex DEL REG 0,28 73 /dev/shm/lQNXel
coverage 1264574 alex DEL REG 0,28 67 /dev/shm/ktswZl
coverage 1264574 alex DEL REG 0,28 57 /dev/shm/NbB97k
coverage 1264574 alex DEL REG 0,28 47 /dev/shm/IXwQdl
coverage 1264574 alex DEL REG 0,28 18 /dev/shm/dIujCk
coverage 1264574 alex DEL REG 0,1 16887081 /dev/zero
coverage 1264574 alex 0u CHR 136,2 0t0 5 /dev/pts/2 7024,gnome-ter,17u
coverage 1264574 alex 1u CHR 136,2 0t0 5 /dev/pts/2 7024,gnome-ter,17u
coverage 1264574 alex 2u CHR 136,2 0t0 5 /dev/pts/2 7024,gnome-ter,17u
coverage 1264574 alex 3r CHR 1,9 0t0 11 /dev/urandom
coverage 1264574 alex 4u unix 0x0000000000000000 0t0 16879956 type=STREAM ->INO=16879957 1264579,coverage,5u
coverage 1264579 alex 5u unix 0x0000000000000000 0t0 16879957 type=STREAM ->INO=16879956 1264574,coverage,4u
FAIL
test_connection_failure_raised (tests.connection_test.MuxShutdownTest) ... 1
ok
test_already_int (tests.connection_test.OptionalIntTest) ... ok
test_is_junk (tests.connection_test.OptionalIntTest) ... ok
test_is_none (tests.connection_test.OptionalIntTest) ... ok
test_is_string (tests.connection_test.OptionalIntTest) ... ok
test_mode (tests.connection_test.PutDataTest) ... ok
test_out_path (tests.connection_test.PutDataTest) ... ok
test_big_in_path_not_found (tests.connection_test.PutFileTest) ... ok
test_out_path_big (tests.connection_test.PutFileTest) ... ok
test_out_path_tiny (tests.connection_test.PutFileTest) ... ok
test_binary_key_added (tests.env_file_watcher_test.WatcherTest) ... ok
test_file_becomes_missing (tests.env_file_watcher_test.WatcherTest) ... ok
test_key_added (tests.env_file_watcher_test.WatcherTest) ... ok
test_key_deleted (tests.env_file_watcher_test.WatcherTest) ... ok
test_key_shadowed_nuchange (tests.env_file_watcher_test.WatcherTest) ... ok
test_missing_file (tests.env_file_watcher_test.WatcherTest) ... ok
test_simple (tests.target_test.ApplyModeSpecTest) ... ok
test_expands_usernames (tests.target_test.FindGoodTempDirTest) ... ok
test_expands_vars (tests.target_test.FindGoodTempDirTest) ... ok
test_no_good_candidate (tests.target_test.FindGoodTempDirTest) ... ok
test_creates (tests.target_test.IsGoodTempDirTest) ... ok
test_file_exists (tests.target_test.IsGoodTempDirTest) ... ok
test_noexec (tests.target_test.IsGoodTempDirTest) ... ok
test_unwriteable (tests.target_test.IsGoodTempDirTest) ... ok
test_weird_filesystem (tests.target_test.IsGoodTempDirTest) ... ok
======================================================================
FAIL: test_success (tests.connection_test.FetchFileTest)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/alex/src/mitogen/tests/ansible/tests/connection_test.py", line 73, in tearDown
super(ConnectionMixin, self).tearDown()
File "/home/alex/src/mitogen/tests/testlib.py", line 382, in tearDown
self._teardown_check_fds()
File "/home/alex/src/mitogen/tests/testlib.py", line 353, in _teardown_check_fds
self, self._fd_count_before, fd_count_after,
AssertionError: test_success (tests.connection_test.FetchFileTest) leaked FDs. Count before: 6, after: 7
----------------------------------------------------------------------
Ran 45 tests in 5.359s
FAILED (failures=1, skipped=1)
Command exited with non-zero status 1
5.15user 0.83system 0:06.35elapsed 94%CPU (0avgtext+0avgdata 55528maxresident)k
48296inputs+20696outputs (83major+105456minor)pagefaults 0swaps
Exception occurred while running: ['/usr/bin/time', '--', './run_tests', '-v']
travis_fold:end:unit_tests
Traceback (most recent call last):
File "/home/alex/src/mitogen/.ci/ansible_tests.py", line 28, in <module>
ci_lib.run('./run_tests -v')
File "/home/alex/src/mitogen/.ci/ci_lib.py", line 92, in run
ret = subprocess.check_call(argv, **kwargs)
File "/usr/lib/python3.6/subprocess.py", line 311, in check_call
raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['/usr/bin/time', '--', './run_tests', '-v']' returned non-zero exit status 1.
ERROR: InvocationError for command /home/alex/src/mitogen/.ci/ansible_tests.py (exited with code 1)
________________________________________________ summary ________________________________________________
ERROR: py36-mode_ansible-ansible29: commands failed
refs #760
If that TOCTOU mismatch described in fd2eae7a3a3c15126124999080ed151fc47e95ee is happening, it still means there's a race somewhere here, and maybe we should try sleeping for a moment to see if the FDs come back down again, (as they do when one waits for the lsof).
Or, even better, get to the bottom of the race, and fix it.
