search

pytest-dev / pytest-asyncio

Asyncio support for pytest
https://pytest-asyncio.readthedocs.io
Apache License 2.0
1.4k stars 145 forks source link

"Event loop is closed" error in `_provide_clean_event_loop()` #548

Closed link2xt closed 1 year ago

link2xt commented 1 year ago

The error sometimes happens during the test teardown.

Here is an example of a failure: https://github.com/deltachat/deltachat-core-rust/actions/runs/5022838715/jobs/9006825246

Slightly cleaned up (removed git clone progress) log:

Failure log ``` 2023-05-19T09:30:28.1963672Z Requested labels: ubuntu-latest 2023-05-19T09:30:28.1964098Z Job defined at: deltachat/deltachat-core-rust/.github/workflows/ci.yml@refs/heads/master 2023-05-19T09:30:28.1964303Z Waiting for a runner to pick up this job... 2023-05-19T09:30:28.4092092Z Job is waiting for a hosted runner to come online. 2023-05-19T09:30:32.4334700Z Job is about to start running on the hosted runner: GitHub Actions 12 (hosted) 2023-05-19T09:30:35.3312448Z Current runner version: '2.304.0' 2023-05-19T09:30:35.3347520Z ##[group]Operating System 2023-05-19T09:30:35.3348307Z Ubuntu 2023-05-19T09:30:35.3348674Z 22.04.2 2023-05-19T09:30:35.3349170Z LTS 2023-05-19T09:30:35.3349597Z ##[endgroup] 2023-05-19T09:30:35.3350020Z ##[group]Runner Image 2023-05-19T09:30:35.3350496Z Image: ubuntu-22.04 2023-05-19T09:30:35.3350915Z Version: 20230507.1 2023-05-19T09:30:35.3351980Z Included Software: https://github.com/actions/runner-images/blob/ubuntu22/20230507.1/images/linux/Ubuntu2204-Readme.md 2023-05-19T09:30:35.3352827Z Image Release: https://github.com/actions/runner-images/releases/tag/ubuntu22%2F20230507.1 2023-05-19T09:30:35.3353982Z ##[endgroup] 2023-05-19T09:30:35.3354554Z ##[group]Runner Image Provisioner 2023-05-19T09:30:35.3355023Z 2.0.171.1 2023-05-19T09:30:35.3355372Z ##[endgroup] 2023-05-19T09:30:35.3357299Z ##[group]GITHUB_TOKEN Permissions 2023-05-19T09:30:35.3358333Z Actions: write 2023-05-19T09:30:35.3358772Z Checks: write 2023-05-19T09:30:35.3359528Z Contents: write 2023-05-19T09:30:35.3360103Z Deployments: write 2023-05-19T09:30:35.3360573Z Discussions: write 2023-05-19T09:30:35.3361006Z Issues: write 2023-05-19T09:30:35.3361408Z Metadata: read 2023-05-19T09:30:35.3361871Z Packages: write 2023-05-19T09:30:35.3362228Z Pages: write 2023-05-19T09:30:35.3362659Z PullRequests: write 2023-05-19T09:30:35.3363121Z RepositoryProjects: write 2023-05-19T09:30:35.3363653Z SecurityEvents: write 2023-05-19T09:30:35.3364091Z Statuses: write 2023-05-19T09:30:35.3364471Z ##[endgroup] 2023-05-19T09:30:35.3369362Z Secret source: Actions 2023-05-19T09:30:35.3370021Z Prepare workflow directory 2023-05-19T09:30:35.4547198Z Prepare all required actions 2023-05-19T09:30:35.4808637Z Getting action download info 2023-05-19T09:30:35.7249563Z Download action repository 'actions/checkout@v3' (SHA:8e5e7e5ab8b370d6c329ec480221332ada57f0ab) 2023-05-19T09:30:36.5159282Z Download action repository 'actions/setup-python@v4' (SHA:57ded4d7d5e986d7296eab16560982c6dd7c923b) 2023-05-19T09:30:37.1693596Z Download action repository 'actions/download-artifact@v3' (SHA:9bc31d5ccc31df68ecc42ccf4149144866c47d8a) 2023-05-19T09:30:37.8234314Z Complete job name: Async Python tests (ubuntu-latest, 3.7) 2023-05-19T09:30:37.9510800Z ##[group]Run actions/checkout@v3 2023-05-19T09:30:37.9511610Z with: 2023-05-19T09:30:37.9511972Z repository: deltachat/deltachat-core-rust 2023-05-19T09:30:37.9512906Z token: *** 2023-05-19T09:30:37.9513264Z ssh-strict: true 2023-05-19T09:30:37.9513743Z persist-credentials: true 2023-05-19T09:30:37.9514119Z clean: true 2023-05-19T09:30:37.9514571Z fetch-depth: 1 2023-05-19T09:30:37.9514847Z lfs: false 2023-05-19T09:30:37.9515170Z submodules: false 2023-05-19T09:30:37.9515580Z set-safe-directory: true 2023-05-19T09:30:37.9515948Z env: 2023-05-19T09:30:37.9516336Z RUSTFLAGS: -Dwarnings 2023-05-19T09:30:37.9516620Z ##[endgroup] 2023-05-19T09:30:38.3231535Z Syncing repository: deltachat/deltachat-core-rust 2023-05-19T09:30:38.3233732Z ##[group]Getting Git version info 2023-05-19T09:30:38.3234399Z Working directory is '/home/runner/work/deltachat-core-rust/deltachat-core-rust' 2023-05-19T09:30:38.3235058Z [command]/usr/bin/git version 2023-05-19T09:30:38.3380949Z git version 2.40.1 2023-05-19T09:30:38.3422401Z ##[endgroup] 2023-05-19T09:30:38.3452555Z Temporarily overriding HOME='/home/runner/work/_temp/391bc45e-d9af-41b1-942e-e25cfd34c11b' before making global git config changes 2023-05-19T09:30:38.3453724Z Adding repository directory to the temporary git global config as a safe directory 2023-05-19T09:30:38.3454982Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/deltachat-core-rust/deltachat-core-rust 2023-05-19T09:30:38.3522544Z Deleting the contents of '/home/runner/work/deltachat-core-rust/deltachat-core-rust' 2023-05-19T09:30:38.3527848Z ##[group]Initializing the repository 2023-05-19T09:30:38.3534027Z [command]/usr/bin/git init /home/runner/work/deltachat-core-rust/deltachat-core-rust 2023-05-19T09:30:38.3712980Z hint: Using 'master' as the name for the initial branch. This default branch name 2023-05-19T09:30:38.3713911Z hint: is subject to change. To configure the initial branch name to use in all 2023-05-19T09:30:38.3715558Z hint: of your new repositories, which will suppress this warning, call: 2023-05-19T09:30:38.3715990Z hint: 2023-05-19T09:30:38.3716460Z hint: git config --global init.defaultBranch 2023-05-19T09:30:38.3716772Z hint: 2023-05-19T09:30:38.3717940Z hint: Names commonly chosen instead of 'master' are 'main', 'trunk' and 2023-05-19T09:30:38.3718541Z hint: 'development'. The just-created branch can be renamed via this command: 2023-05-19T09:30:38.3718863Z hint: 2023-05-19T09:30:38.3719165Z hint: git branch -m 2023-05-19T09:30:38.3719718Z Initialized empty Git repository in /home/runner/work/deltachat-core-rust/deltachat-core-rust/.git/ 2023-05-19T09:30:38.3721793Z [command]/usr/bin/git remote add origin https://github.com/deltachat/deltachat-core-rust 2023-05-19T09:30:38.3805279Z ##[endgroup] 2023-05-19T09:30:38.3806252Z ##[group]Disabling automatic garbage collection 2023-05-19T09:30:38.3809769Z [command]/usr/bin/git config --local gc.auto 0 2023-05-19T09:30:38.3861340Z ##[endgroup] 2023-05-19T09:30:38.3862345Z ##[group]Setting up auth 2023-05-19T09:30:38.3879671Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand 2023-05-19T09:30:38.3931286Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :" 2023-05-19T09:30:38.4427300Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader 2023-05-19T09:30:38.4450179Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :" 2023-05-19T09:30:38.4770974Z [command]/usr/bin/git config --local http.https://github.com/.extraheader AUTHORIZATION: basic *** 2023-05-19T09:30:38.4833597Z ##[endgroup] 2023-05-19T09:30:38.4834657Z ##[group]Fetching the repository 2023-05-19T09:30:38.4847315Z [command]/usr/bin/git -c protocol.version=2 fetch --no-tags --prune --progress --no-recurse-submodules --depth=1 origin +10b2aa535087ee13ab06b0eb9f60ed24a46b68ea:refs/remotes/origin/master 2023-05-19T09:30:38.8491303Z remote: Enumerating objects: 884, done. 2023-05-19T09:30:38.8553420Z remote: Counting objects: 0% (1/884) 2023-05-19T09:30:38.8600882Z remote: Counting objects: 100% (884/884), done. 2023-05-19T09:30:38.8601266Z remote: Compressing objects: 0% (1/695) 2023-05-19T09:30:39.0149100Z remote: Compressing objects: 100% (695/695), done. 2023-05-19T09:30:39.0184866Z Receiving objects: 0% (1/884) 2023-05-19T09:30:39.2552524Z Receiving objects: 98% (867/884) 2023-05-19T09:30:39.2553324Z remote: Total 884 (delta 155), reused 603 (delta 141), pack-reused 0 2023-05-19T09:30:39.2553683Z Receiving objects: 99% (876/884) 2023-05-19T09:30:39.2553953Z Receiving objects: 100% (884/884) 2023-05-19T09:30:39.2554287Z Receiving objects: 100% (884/884), 2.43 MiB | 10.29 MiB/s, done. 2023-05-19T09:30:39.2555154Z Resolving deltas: 0% (0/155) 2023-05-19T09:30:39.2696293Z Resolving deltas: 100% (155/155), done. 2023-05-19T09:30:39.2904022Z From https://github.com/deltachat/deltachat-core-rust 2023-05-19T09:30:39.2905345Z * [new ref] 10b2aa535087ee13ab06b0eb9f60ed24a46b68ea -> origin/master 2023-05-19T09:30:39.2969402Z ##[endgroup] 2023-05-19T09:30:39.2970666Z ##[group]Determining the checkout info 2023-05-19T09:30:39.2971454Z ##[endgroup] 2023-05-19T09:30:39.2972410Z ##[group]Checking out the ref 2023-05-19T09:30:39.2973380Z [command]/usr/bin/git checkout --progress --force -B master refs/remotes/origin/master 2023-05-19T09:30:39.3728849Z Reset branch 'master' 2023-05-19T09:30:39.3738570Z branch 'master' set up to track 'origin/master'. 2023-05-19T09:30:39.3744318Z ##[endgroup] 2023-05-19T09:30:39.3803614Z [command]/usr/bin/git log -1 --format='%H' 2023-05-19T09:30:39.3841220Z '10b2aa535087ee13ab06b0eb9f60ed24a46b68ea' 2023-05-19T09:30:39.4310085Z ##[group]Run actions/setup-python@v4 2023-05-19T09:30:39.4310428Z with: 2023-05-19T09:30:39.4310662Z python-version: 3.7 2023-05-19T09:30:39.4311024Z check-latest: false 2023-05-19T09:30:39.4311695Z token: *** 2023-05-19T09:30:39.4311963Z update-environment: true 2023-05-19T09:30:39.4312262Z allow-prereleases: false 2023-05-19T09:30:39.4312517Z env: 2023-05-19T09:30:39.4312737Z RUSTFLAGS: -Dwarnings 2023-05-19T09:30:39.4313267Z ##[endgroup] 2023-05-19T09:30:39.6510728Z ##[group]Installed versions 2023-05-19T09:30:39.6644342Z Successfully set up CPython (3.7.16) 2023-05-19T09:30:39.6645416Z ##[endgroup] 2023-05-19T09:30:39.6797284Z ##[group]Run pip install tox 2023-05-19T09:30:39.6797704Z pip install tox 2023-05-19T09:30:39.6870868Z shell: /usr/bin/bash -e {0} 2023-05-19T09:30:39.6871996Z env: 2023-05-19T09:30:39.6872298Z RUSTFLAGS: -Dwarnings 2023-05-19T09:30:39.6872660Z pythonLocation: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:39.6873071Z PKG_CONFIG_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib/pkgconfig 2023-05-19T09:30:39.6873478Z Python_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:39.6873865Z Python2_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:39.6874241Z Python3_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:39.6874623Z LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib 2023-05-19T09:30:39.6874965Z ##[endgroup] 2023-05-19T09:30:42.7333282Z Collecting tox 2023-05-19T09:30:42.8806678Z Downloading tox-4.5.1-py3-none-any.whl (148 kB) 2023-05-19T09:30:42.9364504Z ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 149.0/149.0 kB 2.8 MB/s eta 0:00:00 2023-05-19T09:30:43.0565031Z Collecting cachetools>=5.3 (from tox) 2023-05-19T09:30:43.0712649Z Downloading cachetools-5.3.0-py3-none-any.whl (9.3 kB) 2023-05-19T09:30:43.1165197Z Collecting chardet>=5.1 (from tox) 2023-05-19T09:30:43.1323856Z Downloading chardet-5.1.0-py3-none-any.whl (199 kB) 2023-05-19T09:30:43.1608953Z ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 199.1/199.1 kB 7.9 MB/s eta 0:00:00 2023-05-19T09:30:43.2132142Z Collecting colorama>=0.4.6 (from tox) 2023-05-19T09:30:43.2279585Z Downloading colorama-0.4.6-py2.py3-none-any.whl (25 kB) 2023-05-19T09:30:43.2896384Z Collecting filelock>=3.11 (from tox) 2023-05-19T09:30:43.3047409Z Downloading filelock-3.12.0-py3-none-any.whl (10 kB) 2023-05-19T09:30:43.4314938Z Collecting importlib-metadata>=6.4.1 (from tox) 2023-05-19T09:30:43.4459639Z Downloading importlib_metadata-6.6.0-py3-none-any.whl (22 kB) 2023-05-19T09:30:43.5148508Z Collecting packaging>=23.1 (from tox) 2023-05-19T09:30:43.5293097Z Downloading packaging-23.1-py3-none-any.whl (48 kB) 2023-05-19T09:30:43.5374830Z ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 48.9/48.9 kB 9.2 MB/s eta 0:00:00 2023-05-19T09:30:43.5902526Z Collecting platformdirs>=3.2 (from tox) 2023-05-19T09:30:43.6047133Z Downloading platformdirs-3.5.1-py3-none-any.whl (15 kB) 2023-05-19T09:30:43.6585628Z Collecting pluggy>=1 (from tox) 2023-05-19T09:30:43.6726563Z Downloading pluggy-1.0.0-py2.py3-none-any.whl (13 kB) 2023-05-19T09:30:43.7171718Z Collecting pyproject-api>=1.5.1 (from tox) 2023-05-19T09:30:43.7316184Z Downloading pyproject_api-1.5.1-py3-none-any.whl (12 kB) 2023-05-19T09:30:43.7857066Z Collecting tomli>=2.0.1 (from tox) 2023-05-19T09:30:43.8000456Z Downloading tomli-2.0.1-py3-none-any.whl (12 kB) 2023-05-19T09:30:43.8463671Z Collecting typing-extensions>=4.5 (from tox) 2023-05-19T09:30:43.8612579Z Downloading typing_extensions-4.5.0-py3-none-any.whl (27 kB) 2023-05-19T09:30:44.0691919Z Collecting virtualenv>=20.21 (from tox) 2023-05-19T09:30:44.0860314Z Downloading virtualenv-20.23.0-py3-none-any.whl (3.3 MB) 2023-05-19T09:30:44.3254533Z ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 3.3/3.3 MB 13.8 MB/s eta 0:00:00 2023-05-19T09:30:44.4724794Z Collecting zipp>=0.5 (from importlib-metadata>=6.4.1->tox) 2023-05-19T09:30:44.4869047Z Downloading zipp-3.15.0-py3-none-any.whl (6.8 kB) 2023-05-19T09:30:44.6708304Z Collecting distlib<1,>=0.3.6 (from virtualenv>=20.21->tox) 2023-05-19T09:30:44.6858913Z Downloading distlib-0.3.6-py2.py3-none-any.whl (468 kB) 2023-05-19T09:30:44.7188761Z ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 468.5/468.5 kB 16.1 MB/s eta 0:00:00 2023-05-19T09:30:45.0830439Z Installing collected packages: distlib, zipp, typing-extensions, tomli, packaging, filelock, colorama, chardet, cachetools, pyproject-api, platformdirs, importlib-metadata, virtualenv, pluggy, tox 2023-05-19T09:30:45.9799127Z Successfully installed cachetools-5.3.0 chardet-5.1.0 colorama-0.4.6 distlib-0.3.6 filelock-3.12.0 importlib-metadata-6.6.0 packaging-23.1 platformdirs-3.5.1 pluggy-1.0.0 pyproject-api-1.5.1 tomli-2.0.1 tox-4.5.1 typing-extensions-4.5.0 virtualenv-20.23.0 zipp-3.15.0 2023-05-19T09:30:46.3211905Z 2023-05-19T09:30:46.3213767Z [notice] A new release of pip is available: 22.0.4 -> 23.1.2 2023-05-19T09:30:46.3214335Z [notice] To update, run: pip install --upgrade pip 2023-05-19T09:30:46.4849888Z ##[group]Run actions/download-artifact@v3 2023-05-19T09:30:46.4850235Z with: 2023-05-19T09:30:46.4850543Z name: ubuntu-latest-deltachat-rpc-server 2023-05-19T09:30:46.4850864Z path: target/debug 2023-05-19T09:30:46.4851106Z env: 2023-05-19T09:30:46.4851331Z RUSTFLAGS: -Dwarnings 2023-05-19T09:30:46.4851670Z pythonLocation: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:46.4852082Z PKG_CONFIG_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib/pkgconfig 2023-05-19T09:30:46.4852509Z Python_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:46.4852891Z Python2_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:46.4853269Z Python3_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:30:46.4854553Z LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib 2023-05-19T09:30:46.4854931Z ##[endgroup] 2023-05-19T09:30:46.5718270Z Starting download for ubuntu-latest-deltachat-rpc-server 2023-05-19T09:31:18.2813568Z Directory structure has been setup for the artifact 2023-05-19T09:31:18.2820370Z Total number of files that will be downloaded: 1 2023-05-19T09:31:19.2829798Z Total file count: 1 ---- Processed file #0 (0.0%) 2023-05-19T09:31:19.3266688Z Artifact ubuntu-latest-deltachat-rpc-server was downloaded to /home/runner/work/deltachat-core-rust/deltachat-core-rust/target/debug 2023-05-19T09:31:19.3283755Z Artifact download has finished successfully 2023-05-19T09:31:19.3362138Z ##[group]Run chmod +x target/debug/deltachat-rpc-server 2023-05-19T09:31:19.3362590Z chmod +x target/debug/deltachat-rpc-server 2023-05-19T09:31:19.3430795Z shell: /usr/bin/bash -e {0} 2023-05-19T09:31:19.3431069Z env: 2023-05-19T09:31:19.3431809Z RUSTFLAGS: -Dwarnings 2023-05-19T09:31:19.3432149Z pythonLocation: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3432564Z PKG_CONFIG_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib/pkgconfig 2023-05-19T09:31:19.3432969Z Python_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3433348Z Python2_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3433727Z Python3_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3434109Z LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib 2023-05-19T09:31:19.3434406Z ##[endgroup] 2023-05-19T09:31:19.3571806Z ##[group]Run echo /home/runner/work/deltachat-core-rust/deltachat-core-rust/target/debug >> $GITHUB_PATH 2023-05-19T09:31:19.3572432Z echo /home/runner/work/deltachat-core-rust/deltachat-core-rust/target/debug >> $GITHUB_PATH 2023-05-19T09:31:19.3636016Z shell: /usr/bin/bash -e {0} 2023-05-19T09:31:19.3636285Z env: 2023-05-19T09:31:19.3636534Z RUSTFLAGS: -Dwarnings 2023-05-19T09:31:19.3636870Z pythonLocation: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3637377Z PKG_CONFIG_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib/pkgconfig 2023-05-19T09:31:19.3637779Z Python_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3638167Z Python2_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3638544Z Python3_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3638925Z LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib 2023-05-19T09:31:19.3639219Z ##[endgroup] 2023-05-19T09:31:19.3768955Z ##[group]Run tox -e py 2023-05-19T09:31:19.3769269Z tox -e py 2023-05-19T09:31:19.3834692Z shell: /usr/bin/bash -e {0} 2023-05-19T09:31:19.3834980Z env: 2023-05-19T09:31:19.3835547Z RUSTFLAGS: -Dwarnings 2023-05-19T09:31:19.3835906Z pythonLocation: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3836307Z PKG_CONFIG_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib/pkgconfig 2023-05-19T09:31:19.3836710Z Python_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3837091Z Python2_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3837466Z Python3_ROOT_DIR: /opt/hostedtoolcache/Python/3.7.16/x64 2023-05-19T09:31:19.3837846Z LD_LIBRARY_PATH: /opt/hostedtoolcache/Python/3.7.16/x64/lib 2023-05-19T09:31:19.3838421Z DCC_NEW_TMP_EMAIL: *** 2023-05-19T09:31:19.3838681Z ##[endgroup] 2023-05-19T09:31:20.2990043Z py: install_deps> python -I -m pip install aiodns aiohttp pytest pytest-asyncio pytest-timeout 2023-05-19T09:31:28.2868021Z .pkg: install_requires> python -I -m pip install 'setuptools>=45' 'setuptools_scm[toml]>=6.2' 2023-05-19T09:31:31.0151406Z .pkg: _optional_hooks> python /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/site-packages/pyproject_api/_backend.py True setuptools.build_meta 2023-05-19T09:31:31.3967209Z .pkg: get_requires_for_build_sdist> python /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/site-packages/pyproject_api/_backend.py True setuptools.build_meta 2023-05-19T09:31:32.2180306Z .pkg: freeze> python -m pip freeze --all 2023-05-19T09:31:32.7056495Z .pkg: importlib-metadata==6.6.0,packaging==23.1,pip==23.1.2,setuptools==67.7.2,setuptools-scm==7.1.0,tomli==2.0.1,typing_extensions==4.5.0,wheel==0.40.0,zipp==3.15.0 2023-05-19T09:31:32.7064486Z .pkg: build_sdist> python /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/site-packages/pyproject_api/_backend.py True setuptools.build_meta 2023-05-19T09:31:32.9239918Z py: install_package_deps> python -I -m pip install aiodns aiohttp 2023-05-19T09:31:34.0865330Z py: install_package> python -I -m pip install --force-reinstall --no-deps /home/runner/work/deltachat-core-rust/deltachat-core-rust/deltachat-rpc-client/.tox/.tmp/package/1/deltachat-rpc-client-0.1.dev1+g10b2aa5.tar.gz 2023-05-19T09:31:42.3358793Z py: freeze> python -m pip freeze --all 2023-05-19T09:31:42.9021674Z py: aiodns==3.0.0,aiohttp==3.8.4,aiosignal==1.3.1,async-timeout==4.0.2,asynctest==0.13.0,attrs==23.1.0,cffi==1.15.1,charset-normalizer==3.1.0,deltachat-rpc-client @ file:///home/runner/work/deltachat-core-rust/deltachat-core-rust/deltachat-rpc-client/.tox/.tmp/package/1/deltachat-rpc-client-0.1.dev1%2Bg10b2aa5.tar.gz#sha256=00c1eaf328300b9a1f8df442339db949a6edd4e23e63cb74e6b89cd7383bbd1b,exceptiongroup==1.1.1,frozenlist==1.3.3,idna==3.4,importlib-metadata==6.6.0,iniconfig==2.0.0,multidict==6.0.4,packaging==23.1,pip==23.1.2,pluggy==1.0.0,pycares==4.3.0,pycparser==2.21,pytest==7.3.1,pytest-asyncio==0.21.0,pytest-timeout==2.1.0,setuptools==67.7.2,tomli==2.0.1,typing_extensions==4.5.0,wheel==0.40.0,yarl==1.9.2,zipp==3.15.0 2023-05-19T09:31:42.9030827Z py: commands[0]> pytest 2023-05-19T09:31:43.7411800Z ============================= test session starts ============================== 2023-05-19T09:31:43.7412732Z platform linux -- Python 3.7.16, pytest-7.3.1, pluggy-1.0.0 2023-05-19T09:31:43.7413118Z cachedir: .tox/py/.pytest_cache 2023-05-19T09:31:43.7413670Z rootdir: /home/runner/work/deltachat-core-rust/deltachat-core-rust/deltachat-rpc-client 2023-05-19T09:31:43.7414052Z configfile: tox.ini 2023-05-19T09:31:43.7414560Z plugins: deltachat-rpc-client-0.1.dev1+g10b2aa5, timeout-2.1.0, asyncio-0.21.0 2023-05-19T09:31:43.7414944Z timeout: 60.0s 2023-05-19T09:31:43.7415207Z timeout method: signal 2023-05-19T09:31:43.7415488Z timeout func_only: False 2023-05-19T09:31:43.7415742Z asyncio: mode=strict 2023-05-19T09:31:43.7416086Z collected 13 items 2023-05-19T09:31:43.7416243Z 2023-05-19T09:33:09.6068144Z tests/test_something.py .E........... [ 92%] 2023-05-19T09:33:18.3089313Z tests/test_webxdc.py . [100%] 2023-05-19T09:33:18.3090086Z 2023-05-19T09:33:18.3091572Z ==================================== ERRORS ==================================== 2023-05-19T09:33:18.3092619Z ____________________ ERROR at teardown of test_system_info _____________________ 2023-05-19T09:33:18.3093366Z 2023-05-19T09:33:18.3094081Z def _provide_clean_event_loop() -> None: 2023-05-19T09:33:18.3094599Z # At this point, the event loop for the current thread is closed. 2023-05-19T09:33:18.3095191Z # When a user calls asyncio.get_event_loop(), they will get a closed loop. 2023-05-19T09:33:18.3095953Z # In order to avoid this side effect from pytest-asyncio, we need to replace 2023-05-19T09:33:18.3096754Z # the current loop with a fresh one. 2023-05-19T09:33:18.3097238Z # Note that we cannot set the loop to None, because get_event_loop only creates 2023-05-19T09:33:18.3098276Z # a new loop, when set_event_loop has not been called. 2023-05-19T09:33:18.3098945Z policy = asyncio.get_event_loop_policy() 2023-05-19T09:33:18.3099538Z new_loop = policy.new_event_loop() 2023-05-19T09:33:18.3099902Z > policy.set_event_loop(new_loop) 2023-05-19T09:33:18.3100135Z 2023-05-19T09:33:18.3100592Z .tox/py/lib/python3.7/site-packages/pytest_asyncio/plugin.py:460: 2023-05-19T09:33:18.3101059Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 2023-05-19T09:33:18.3101675Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py:1134: in set_event_loop 2023-05-19T09:33:18.3102176Z self._watcher.attach_loop(loop) 2023-05-19T09:33:18.3102684Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py:889: in attach_loop 2023-05-19T09:33:18.3103159Z self._do_waitpid_all() 2023-05-19T09:33:18.3103609Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py:959: in _do_waitpid_all 2023-05-19T09:33:18.3104133Z self._do_waitpid(pid) 2023-05-19T09:33:18.3104611Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py:993: in _do_waitpid 2023-05-19T09:33:18.3105100Z callback(pid, returncode, *args) 2023-05-19T09:33:18.3105644Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py:204: in _child_watcher_callback 2023-05-19T09:33:18.3106252Z self.call_soon_threadsafe(transp._process_exited, returncode) 2023-05-19T09:33:18.3106758Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_events.py:736: in call_soon_threadsafe 2023-05-19T09:33:18.3107239Z self._check_closed() 2023-05-19T09:33:18.3107642Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 2023-05-19T09:33:18.3107872Z 2023-05-19T09:33:18.3108195Z self = <_UnixSelectorEventLoop running=False closed=True debug=False> 2023-05-19T09:33:18.3108646Z 2023-05-19T09:33:18.3108805Z def _check_closed(self): 2023-05-19T09:33:18.3109241Z if self._closed: 2023-05-19T09:33:18.3110494Z > raise RuntimeError('Event loop is closed') 2023-05-19T09:33:18.3110953Z E RuntimeError: Event loop is closed 2023-05-19T09:33:18.3111452Z 2023-05-19T09:33:18.3112081Z /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_events.py:479: RuntimeError 2023-05-19T09:33:18.3112809Z ----------------------------- Captured stderr call ----------------------------- 2023-05-19T09:33:18.3113674Z [2023-05-19T09:31:43Z INFO deltachat_rpc_server] Starting with accounts directory `/tmp/pytest-of-runner/pytest-0/test_system_info0/accounts`. 2023-05-19T09:33:18.3114388Z [2023-05-19T09:31:43Z INFO deltachat_rpc_server] Creating JSON-RPC API. 2023-05-19T09:33:18.3115094Z --------------------------- Captured stderr teardown --------------------------- 2023-05-19T09:33:18.3115632Z [2023-05-19T09:31:43Z INFO deltachat_rpc_server] got SIGTERM 2023-05-19T09:33:18.3116092Z =========================== short test summary info ============================ 2023-05-19T09:33:18.3117191Z ERROR tests/test_something.py::test_system_info - RuntimeError: Event loop is... 2023-05-19T09:33:18.3117783Z ==================== 13 passed, 1 error in 94.67s (0:01:34) ==================== 2023-05-19T09:33:18.3633421Z Exception ignored in: 2023-05-19T09:33:18.3634002Z Traceback (most recent call last): 2023-05-19T09:33:18.3647159Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_subprocess.py", line 127, in __del__ 2023-05-19T09:33:18.3647884Z self.close() 2023-05-19T09:33:18.3648502Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_subprocess.py", line 104, in close 2023-05-19T09:33:18.3649017Z proto.pipe.close() 2023-05-19T09:33:18.3649503Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py", line 718, in close 2023-05-19T09:33:18.3650005Z self.write_eof() 2023-05-19T09:33:18.3650640Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/unix_events.py", line 704, in write_eof 2023-05-19T09:33:18.3651193Z self._loop.call_soon(self._call_connection_lost, None) 2023-05-19T09:33:18.3651778Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_events.py", line 691, in call_soon 2023-05-19T09:33:18.3652277Z self._check_closed() 2023-05-19T09:33:18.3652883Z File "/opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/asyncio/base_events.py", line 479, in _check_closed 2023-05-19T09:33:18.3728614Z ##[error] raise RuntimeError('Event loop is closed') 2023-05-19T09:33:18.3739537Z RuntimeError: Event loop is closed 2023-05-19T09:33:18.3789949Z py: exit 1 (95.47 seconds) /home/runner/work/deltachat-core-rust/deltachat-core-rust/deltachat-rpc-client> pytest pid=1847 2023-05-19T09:33:18.3836020Z .pkg: _exit> python /opt/hostedtoolcache/Python/3.7.16/x64/lib/python3.7/site-packages/pyproject_api/_backend.py True setuptools.build_meta 2023-05-19T09:33:18.4393198Z py: FAIL code 1 (118.61=setup[23.14]+cmd[95.47] seconds) 2023-05-19T09:33:18.4393686Z evaluation failed :( (118.81 seconds) 2023-05-19T09:33:18.4846387Z ##[error]Process completed with exit code 1. 2023-05-19T09:33:18.4918359Z Post job cleanup. 2023-05-19T09:33:18.6327096Z [command]/usr/bin/git version 2023-05-19T09:33:18.6413776Z git version 2.40.1 2023-05-19T09:33:18.6485874Z Temporarily overriding HOME='/home/runner/work/_temp/198e0afd-acdd-4d76-84e1-8d329f4578bc' before making global git config changes 2023-05-19T09:33:18.6488226Z Adding repository directory to the temporary git global config as a safe directory 2023-05-19T09:33:18.6498871Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/deltachat-core-rust/deltachat-core-rust 2023-05-19T09:33:18.6572092Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand 2023-05-19T09:33:18.6627955Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :" 2023-05-19T09:33:18.6987089Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader 2023-05-19T09:33:18.7032917Z http.https://github.com/.extraheader 2023-05-19T09:33:18.7038470Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader 2023-05-19T09:33:18.7085401Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :" 2023-05-19T09:33:18.7670777Z Cleaning up orphan processes ```
seifertm commented 1 year ago

Thanks for providing the logs and the link to the project sources.

Unfortunately, I cannot reproduce the error locally. After building deltachat-rpc-server I was able to run tox run -- -k test_system_info successfully multiple times on Python 3.7 and Python 3.11.

From the top of my head there are two things you can do. If the error occurs with Python 3.7 only, you may consider testing with Python 3.8. Major parts of asyncio have been rewritten in Python 3.8 and Python 3.7 will reach end-of-life in roughly 6 weeks.

Alternatively, you can try to isolate the error in a simpler example. Your setup is quite complex and involves building executables and creating online accounts to run the tests. If you can create a minimal example that reproduces the issue, chances are much higher that we can help you.

link2xt commented 1 year ago

I also cannot reproduce it locally, it happens randomly on GitHub Actions. Maybe GitHub runner pauses the processes or otherwise triggers race conditions that do not happen when you run the tests on a dev machine.

I mostly hoped that something can be figured out of the backtrace.

This seems to be somehow related to having a subprocess, and deltachat-rpc-client Python library indeed starts a deltachat-rpc-server Rust binary as a subprocess.

The backtrace in a better form:

So attach_loop of the child watcher is called here: https://github.com/python/cpython/blob/v3.7.16/Lib/asyncio/unix_events.py#L1134

Then new loop is set and _do_waitpid_all is called: https://github.com/python/cpython/blob/v3.7.16/Lib/asyncio/unix_events.py#L887-L889 Note the comment about the race condition.

Apparently this race condition happens and a child indeed terminated but was not handled while previous loop was set. So we are handling it now, right after switching to a new loop.

A child handler callback is called, which is actually a _child_watcher_callback. This callback only calls self.call_soon_threadsafe which expects the current loop to be open. And it indeed should be open because we have just created and set it. I don't understand what is wrong there.

link2xt commented 1 year ago

There is indeed something different about how setting event loop is handled in Python 3.7. I have created an example:

import subprocess
import asyncio
import time
import signal

async def main():
    policy = asyncio.get_event_loop_policy()
    new_loop = policy.new_event_loop()

    subprocess = await asyncio.create_subprocess_exec("sleep", "5")
    policy.set_event_loop(new_loop)

if __name__ == "__main__":
    asyncio.run(main())

This produces a warning "RuntimeWarning: A loop is being detached from a child watcher with pending handlers" with Python 3.7, but not with Python 3.8.

The warning about loop being detached is produced when the loop is set to None: https://github.com/python/cpython/blob/v3.7.16/Lib/asyncio/unix_events.py#L874-L878

So somehow with Python 3.7 policy.set_event_loop() is setting the loop to None in this case. This is different from the bug observed in the log though, where the loop is not None, but closed. Maybe old loop is used for some reason.

One difference I see comparing 3.8.0 to 3.7.16 is that default child watcher is changed to ThreadedChildWatcher. As of 3.11 it is still the default child watcher: https://docs.python.org/3.11/library/asyncio-policy.html The change was introduced in https://github.com/python/cpython/pull/14344 It is indeed a big difference, I will try to replace Python 3.7 with Python 3.8 as the minimum supported version and see if this error appears.

As for pytest-asyncio, maybe it is possible to somehow avoid setting global/thread-local variables and make it less stateful to avoid such problems on the architectural level? Just a thought, I did not even read the whole asyncio documentation.

link2xt commented 1 year ago

I am going to drop support for Python 3.7 at https://github.com/deltachat/deltachat-core-rust/pull/4410

If getting rid of set_event_loop() call is not feasible, feel free to close the issue.

seifertm commented 1 year ago

Thanks for the thorough investigation and summary!

This sounds like a duplicate of #114. The issue was closed a couple of months ago, because it's unlikely that anyone is going to backport the asyncio.ThreadedChildWatcher to Python 3.7.

As for pytest-asyncio, maybe it is possible to somehow avoid setting global/thread-local variables and make it less stateful to avoid such problems on the architectural level? Just a thought, I did not even read the whole asyncio documentation.

If getting rid of set_event_loop() call is not feasible, feel free to close the issue.

Right now, pytest-asyncio uses _get_eventloop() during setup of the _eventloop fixture. Unfortunately, _get_eventloop creates a new loop when no loop has been set or returns the old loop when _set_eventloop was called. The goal is to get rid of both _get_eventloop and _set_eventloop calls, especially due to recent changes to get_event_loop. [0]

The problem is that pytest-asyncio currently uses _get_event_loop to clean up unclosed event loops for the users. Technically, this is "bad loop hygene", but we cannot just remove the functionality without warning. Therefore, pytest-asyncio emits a DeprecationWarning since v0.21 when it closes an event loop for the user. The plan is to remove that functionality in future versions of pytest-asyncio.

I'll close this as a duplicate of #114. Feel free to continue the discussion, though.

[0] https://github.com/python/cpython/issues/93453