SMTP: failed to connect: io: operation would block

[Hocuri]

• Operating System (Linux/Mac/Windows/iOS/Android): Android
• Delta Chat Version: master
• Expected behavior:
• Actual behavior: configure sometimes fails with SMTP: failed to connect: io: operation would block; i'd say it's only when I have flaky network. Happens since about 1-2 weeks.
• Steps to reproduce the problem:
• Logs:

  09-29 22:29:09.064 12468 12510 I DeltaChat: src/context.rs:165: stopping IO
  09-29 22:29:09.065 12468 12510 I DeltaChat: src/context.rs:167: IO is not running
  09-29 22:29:09.066 12468 12510 I DeltaChat: src/configure/mod.rs:81: Configure ...
  09-29 22:29:09.081 12468 12510 I DeltaChat: src/configure/mod.rs:448: checking internal provider-info for offline autoconfig
  09-29 22:29:09.082 12468 12510 I DeltaChat: src/configure/mod.rs:460: offline autoconfig found
  09-29 22:29:09.083 12468 12510 I DeltaChat: src/configure/mod.rs:506: Trying: imap: ***@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false
  09-29 22:29:09.084 12468 12510 I DeltaChat: src/configure/mod.rs:531: Trying: smtp: ***@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=automatic oauth2=false
  09-29 22:29:10.074 12468 12510 I DeltaChat: src/configure/mod.rs:534: failure: SMTP: failed to connect: io: operation would block
  09-29 22:29:10.617 12468 12510 I DeltaChat: src/configure/mod.rs:515: success: imap: ***@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false
  09-29 22:29:10.624 12468 12510 I DeltaChat: src/configure/mod.rs:91: apply config_defaults bcc_self=1
  09-29 22:29:10.644 12468 12510 I DeltaChat: src/configure/mod.rs:91: apply config_defaults sentbox_watch=0
  09-29 22:29:10.650 12468 12510 I DeltaChat: src/configure/mod.rs:91: apply config_defaults mvbox_watch=0
  09-29 22:29:10.657 12468 12510 I DeltaChat: src/configure/mod.rs:91: apply config_defaults mvbox_move=0
  09-29 22:29:10.664 12468 12468 I DeltaChat: ++++++++++++++++++ ApplicationDcContext.maybeStartIo() ++++++++++++++++++
  09-29 22:29:10.664 12468 12510 W DeltaChat: deltachat-ffi/src/lib.rs:3246: Configure failed: SMTP: failed to connect: io: operation would block

  "SMTP: failed to connect" comes from ConnectionFailure error (the string appears nowhere else in the repo). This error is only used here: https://github.com/deltachat/deltachat-core-rust/blob/637d2661e801b91c1ebd7bc2f158d8f80e5ce72b/src/smtp/mod.rs#L211-L212

Update: I found where the "io:" comes from: It has to be async-smtp-0.3.4/src/smtp/error.rs line 38:

    /// IO error
    #[error("io: {0}")]
    Io(#[from] io::Error),

[Hocuri]

Ok maybe it's not a bug at all. I found std::io::error::ErrorKind::WouldBlock which becomes "operation would block" (it was in ~/.rustup). And apperently WouldBlock can mean that the operation timed out which would be normal on flaky network conditions. I'll see if it also sometimes happens with non-flaky network.

[Hocuri]

Now this CI failed: https://app.circleci.com/pipelines/github/deltachat/deltachat-core-rust/6700/workflows/d1ec9ee6-98f1-4d02-baca-a6fa7064dc84/jobs/27395.

The log also contained the line 4.35 [events-ac2] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: async_native_tls: operation would block but apparently DC succeeded with another IMAP config later. @dignifiedquire @link2xt do you know anything about this? Even if it's just a timeout we should still try to improve the error message.

Full log:

``` --- Copying files to ci@b1.delta.chat:ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395 + ssh -oBatchMode=yes -oStrictHostKeyChecking=no ci@b1.delta.chat mkdir -p ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395 Warning: Permanently added 'b1.delta.chat,5.9.136.70' (ECDSA) to the list of known hosts. + git ls-files + find .git + rsync --delete --files-from=.rsynclist -az ./ ci@b1.delta.chat:ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395 + set +x --- Running remote_tests_python remotely Pseudo-terminal will not be allocated because stdin is not a terminal. Welcome to Ubuntu 18.04.5 LTS (GNU/Linux 4.15.0-112-generic x86_64) System information disabled due to load higher than 12.0 1 package can be updated. 0 updates are security updates. New release '20.04.1 LTS' available. Run 'do-release-upgrade' to upgrade to it. *** System restart required *** + which python /usr/bin/python + source /home/ci/venv/bin/activate ++ deactivate nondestructive ++ unset -f pydoc ++ '[' -z '' ']' ++ '[' -z '' ']' ++ '[' -n /bin/bash ']' ++ hash -r ++ '[' -z '' ']' ++ unset VIRTUAL_ENV ++ '[' '!' nondestructive = nondestructive ']' ++ VIRTUAL_ENV=/home/ci/venv ++ export VIRTUAL_ENV ++ _OLD_VIRTUAL_PATH=/home/ci/.cargo/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin ++ PATH=/home/ci/venv/bin:/home/ci/.cargo/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin ++ export PATH ++ '[' -z '' ']' ++ '[' -z '' ']' ++ _OLD_VIRTUAL_PS1= ++ '[' x '!=' x ']' +++ basename /home/ci/venv ++ PS1='(venv) ' ++ export PS1 ++ alias pydoc ++ '[' -n /bin/bash ']' ++ hash -r + which python /home/ci/venv/bin/python + bash ci_scripts/run-python-test.sh + shopt -s huponexit + export DCC_RS_TARGET=debug + DCC_RS_TARGET=debug ++ pwd + export DCC_RS_DEV=/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395 + DCC_RS_DEV=/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395 + cd python + python install_python_bindings.py onlybuild Compiling version_check v0.9.2 Compiling proc-macro2 v1.0.23 Compiling cfg-if v0.1.10 Compiling unicode-xid v0.2.1 Compiling syn v1.0.42 Compiling autocfg v1.0.1 Compiling libc v0.2.77 Compiling memchr v2.3.3 Compiling typenum v1.12.0 Compiling byteorder v1.3.4 Compiling spin v0.5.2 Compiling serde_derive v1.0.116 Compiling serde v1.0.116 Compiling log v0.4.11 Compiling once_cell v1.4.1 Compiling getrandom v0.1.15 Compiling futures-core v0.3.5 Compiling cc v1.0.60 Compiling futures-io v0.3.5 Compiling opaque-debug v0.3.0 Compiling ppv-lite86 v0.2.9 Compiling pkg-config v0.3.18 Compiling cache-padded v1.1.1 Compiling subtle v2.3.0 Compiling fastrand v1.3.5 Compiling pin-utils v0.1.0 Compiling percent-encoding v2.1.0 Compiling waker-fn v1.1.0 Compiling matches v0.1.8 Compiling parking v2.0.0 Compiling bitflags v1.2.1 Compiling pin-project-lite v0.1.8 Compiling slab v0.4.2 Compiling proc-macro-hack v0.5.18 Compiling block-padding v0.2.1 Compiling vec-arena v1.0.0 Compiling tinyvec v0.3.4 Compiling event-listener v2.5.1 Compiling async-task v4.0.2 Compiling ryu v1.0.5 Compiling pin-project-internal v0.4.24 Compiling atomic-waker v1.0.0 Compiling smallvec v1.4.2 Compiling base64 v0.12.3 Compiling cpuid-bool v0.1.2 Compiling proc-macro-nested v0.1.6 Compiling regex-syntax v0.6.18 Compiling futures-sink v0.3.5 Compiling maybe-uninit v2.0.0 Compiling itoa v0.4.6 Compiling encoding_index_tests v0.1.4 Compiling foreign-types-shared v0.1.1 Compiling adler v0.2.3 Compiling openssl v0.10.30 Compiling const_fn v0.4.2 Compiling opaque-debug v0.2.3 Compiling native-tls v0.2.4 Compiling encoding_rs v0.8.24 Compiling serde_json v1.0.57 Compiling crc32fast v1.2.0 Compiling lexical-core v0.7.4 Compiling anyhow v1.0.32 Compiling fnv v1.0.7 Compiling stable_deref_trait v1.2.0 Compiling unicode-segmentation v1.6.0 Compiling openssl-probe v0.1.2 Compiling gimli v0.22.0 Compiling ident_case v1.0.1 Compiling strsim v0.9.3 Compiling arrayvec v0.5.1 Compiling object v0.20.0 Compiling linked-hash-map v0.5.3 Compiling libm v0.2.1 Compiling rustc-demangle v0.1.16 Compiling autocfg v0.1.7 Compiling scopeguard v1.1.0 Compiling http-types v2.5.0 Compiling httparse v1.3.4 Compiling data-encoding v2.3.0 Compiling static_assertions v1.1.0 Compiling infer v0.2.3 Compiling hex v0.4.2 Compiling ascii_utils v0.9.3 Compiling match_cfg v0.1.0 Compiling adler32 v1.2.0 Compiling version_check v0.1.5 Compiling base64 v0.11.0 Compiling signature v1.2.2 Compiling quick-error v1.2.3 Compiling derive_builder v0.9.0 Compiling crc24 v0.1.6 Compiling mime v0.3.16 Compiling safemem v0.3.3 Compiling color_quant v1.0.1 Compiling weezl v0.1.0 Compiling dtoa v0.4.6 Compiling fallible-streaming-iterator v0.1.9 Compiling keccak v0.1.0 Compiling fallible-iterator v0.2.0 Compiling bufstream v0.1.4 Compiling quoted_printable v0.4.2 Compiling either v1.6.1 Compiling circular v0.3.0 Compiling bytemuck v1.4.1 Compiling bitfield v0.13.2 Compiling hashbrown v0.9.1 Compiling mutate_once v0.1.1 Compiling entities v1.0.1 Compiling termcolor v1.1.0 Compiling deltachat_ffi v1.46.0 (/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/deltachat-ffi) Compiling strum v0.19.2 Compiling instant v0.1.7 Compiling try_from v0.3.2 Compiling lazy_static v1.4.0 Compiling generic-array v0.14.4 Compiling standback v0.2.10 Compiling time v0.2.22 Compiling unicase v2.6.0 Compiling cookie v0.14.2 Compiling nom v5.1.2 Compiling email v0.0.21 (https://github.com/deltachat/rust-email#9161f2d4) Compiling crossbeam-utils v0.7.2 Compiling num-traits v0.2.12 Compiling num-integer v0.1.43 Compiling miniz_oxide v0.4.2 Compiling num-iter v0.1.41 Compiling num-bigint v0.2.6 Compiling num-rational v0.3.0 Compiling indexmap v1.6.0 Compiling futures-task v0.3.5 Compiling openssl-src v111.11.0+1.1.1h Compiling clear_on_drop v0.2.4 Compiling concurrent-queue v1.2.2 Compiling libsqlite3-sys v0.20.0 Compiling unicode-bidi v0.3.4 Compiling form_urlencoded v1.0.0 Compiling unicode-normalization v0.1.13 Compiling async-mutex v1.4.0 Compiling futures-channel v0.3.5 Compiling foreign-types v0.3.2 Compiling encoding-index-japanese v1.20141219.5 Compiling encoding-index-tradchinese v1.20141219.5 Compiling encoding-index-korean v1.20141219.5 Compiling encoding-index-simpchinese v1.20141219.5 Compiling encoding-index-singlebyte v1.20141219.5 Compiling heck v0.3.1 Compiling lru-cache v0.1.2 Compiling lock_api v0.4.1 Compiling num-bigint-dig v0.6.0 Compiling fast_chemail v0.9.6 Compiling miniz_oxide v0.3.7 Compiling addr2line v0.13.0 Compiling nom v4.2.3 Compiling ed25519 v1.0.2 Compiling gif v0.11.1 Compiling itertools v0.9.0 Compiling kamadak-exif v0.5.2 Compiling escaper v0.1.0 Compiling thread_local v1.0.1 Compiling openssl-sys v0.9.58 Compiling async-channel v1.4.2 Compiling idna v0.2.0 Compiling encoding v0.2.33 Compiling kv-log-macro v1.0.7 Compiling lettre v0.9.2 (https://github.com/deltachat/lettre#12e4f22d) Compiling futures-lite v1.8.0 Compiling aho-corasick v0.7.13 Compiling buf_redux v0.8.4 Compiling quick-xml v0.18.1 Compiling quote v1.0.7 Compiling polling v1.1.0 Compiling nb-connect v1.0.0 Compiling num_cpus v1.13.0 Compiling time v0.1.44 Compiling parking_lot_core v0.8.0 Compiling hostname v0.3.1 Compiling filetime v0.2.12 Compiling hostname v0.1.5 Compiling xattr v0.2.2 Compiling base64 v0.10.1 Compiling deflate v0.8.6 Compiling jpeg-decoder v0.1.20 Compiling mime_guess v2.0.3 Compiling async-executor v1.3.0 Compiling blocking v1.0.0 Compiling crossbeam-queue v0.2.3 Compiling regex v1.3.9 Compiling backtrace v0.3.50 Compiling flate2 v1.0.17 Compiling rand_core v0.5.1 Compiling async-io v1.1.4 Compiling resolv-conf v0.6.3 Compiling parking_lot v0.11.0 Compiling charset v0.1.2 Compiling png v0.16.7 Compiling digest v0.9.0 Compiling block-buffer v0.9.0 Compiling block-cipher v0.8.0 Compiling universal-hash v0.4.0 Compiling block-cipher v0.7.1 Compiling crypto-mac v0.8.0 Compiling aead v0.3.2 Compiling byte-pool v0.2.2 Compiling rusqlite v0.24.0 Compiling rand_chacha v0.2.2 Compiling chrono v0.4.18 Compiling async-global-executor v1.3.0 Compiling scheduled-thread-pool v0.2.5 Compiling pem v0.8.1 Compiling os_type v2.2.0 Compiling sanitize-filename v0.2.1 Compiling mailparse v0.13.0 Compiling sha2 v0.9.1 Compiling md-5 v0.9.1 Compiling sha3 v0.9.1 Compiling ripemd160 v0.9.1 Compiling sha-1 v0.9.1 Compiling stream-cipher v0.7.1 Compiling aes-soft v0.5.0 Compiling block-modes v0.6.1 Compiling blowfish v0.6.0 Compiling cast5 v0.8.0 Compiling twofish v0.4.0 Compiling des v0.5.0 Compiling aes-soft v0.4.0 Compiling hmac v0.8.1 Compiling polyval v0.4.0 Compiling rand v0.7.3 Compiling r2d2 v0.8.9 Compiling image v0.23.10 Compiling simple_asn1 v0.4.1 Compiling cfb-mode v0.5.0 Compiling aes v0.5.0 Compiling hkdf v0.9.0 Compiling aes v0.4.0 Compiling ghash v0.3.0 Compiling r2d2_sqlite v0.17.0 Compiling synstructure v0.12.4 Compiling darling_core v0.10.2 Compiling thiserror-impl v1.0.20 Compiling async-attributes v1.1.1 Compiling futures-macro v0.3.5 Compiling time-macros-impl v0.1.1 Compiling async-trait v0.1.40 Compiling enum-as-inner v0.3.3 Compiling rental-impl v0.5.5 Compiling num-derive v0.3.2 Compiling deltachat_derive v2.0.0 (/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/deltachat_derive) Compiling strum_macros v0.19.2 Compiling aes-gcm v0.6.0 Compiling zeroize_derive v1.0.1 Compiling imap-proto v0.10.2 Compiling darling_macro v0.10.2 Compiling async-std v1.6.5 Compiling time-macros v0.1.0 Compiling thiserror v1.0.20 Compiling encoded-words v0.1.0 (https://github.com/async-email/encoded-words#2631c258) Compiling zeroize v1.1.1 Compiling darling v0.10.2 Compiling curve25519-dalek v3.0.0 Compiling derive_builder_core v0.9.0 Compiling x25519-dalek v1.1.0 Compiling pin-project v0.4.24 Compiling futures-util v0.3.5 Compiling stop-token v0.1.2 Compiling async-tar v0.3.0 Compiling url v2.1.1 Compiling serde_urlencoded v0.7.0 Compiling serde_qs v0.7.0 Compiling uuid v0.8.1 Compiling toml v0.5.6 Compiling ed25519-dalek v1.0.1 Compiling futures-executor v0.3.5 Compiling serde_urlencoded v0.6.1 Compiling lettre_email v0.9.2 (https://github.com/deltachat/lettre#12e4f22d) Compiling rsa v0.3.0 Compiling futures v0.3.5 Compiling human-panic v1.0.3 Compiling trust-dns-proto v0.19.5 Compiling pgp v0.7.1 Compiling trust-dns-resolver v0.19.5 Compiling async-std-resolver v0.19.5 Compiling rental v0.5.5 Compiling async-h1 v2.1.2 Compiling async-native-tls v0.3.3 Compiling http-client v6.0.0 Compiling async-imap v0.4.0 Compiling async-smtp v0.3.4 (https://github.com/async-email/async-smtp?rev=2275fd8d13e39b2c58d6605c786ff06ff9e05708#2275fd8d) Compiling surf v2.0.0-alpha.6 Compiling deltachat v1.46.0 (/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395) Finished dev [unoptimized + debuginfo] target(s) in 2m 47s running: cargo build -p deltachat_ffi + rm -rf tests/__pycache__ + rm -rf src/deltachat/__pycache__ + export PYTHONDONTWRITEBYTECODE=1 + PYTHONDONTWRITEBYTECODE=1 + tox -e lint lint create: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/lint lint installdeps: flake8, pygments, restructuredtext_lint lint installed: docutils==0.16,flake8==3.8.3,importlib-metadata==2.0.0,mccabe==0.6.1,pycodestyle==2.6.0,pyflakes==2.2.0,Pygments==2.7.1,restructuredtext-lint==1.3.1,zipp==3.2.0 lint run-test-pre: PYTHONHASHSEED='1062877832' lint run-test: commands[0] | flake8 src/deltachat lint run-test: commands[1] | flake8 tests/ examples/ lint run-test: commands[2] | rst-lint --encoding utf-8 README.rst ___________________________________ summary ____________________________________ lint: commands succeeded congratulations :) + tox -e doc,py37 GLOB sdist-make: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/setup.py doc create: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/doc doc installdeps: sphinx, breathe doc inst: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/.tmp/package/1/deltachat-1.40.2.dev308+g454271f5.zip doc installed: alabaster==0.7.12,Babel==2.8.0,breathe==4.22.1,certifi==2020.6.20,cffi==1.14.3,chardet==3.0.4,deltachat==1.40.2.dev308+g454271f5,docutils==0.16,idna==2.10,imagesize==1.2.0,IMAPClient==2.1.0,importlib-metadata==2.0.0,Jinja2==2.11.2,MarkupSafe==1.1.1,packaging==20.4,pluggy==0.13.1,pycparser==2.20,Pygments==2.7.1,pyparsing==2.4.7,pytz==2020.1,requests==2.24.0,six==1.15.0,snowballstemmer==2.0.0,Sphinx==3.2.1,sphinxcontrib-applehelp==1.0.2,sphinxcontrib-devhelp==1.0.2,sphinxcontrib-htmlhelp==1.0.3,sphinxcontrib-jsmath==1.0.1,sphinxcontrib-qthelp==1.0.3,sphinxcontrib-serializinghtml==1.1.4,urllib3==1.25.10,zipp==3.2.0 doc run-test-pre: PYTHONHASHSEED='558905713' doc run-test: commands[0] | sphinx-build -Q -w toxdoc-warnings.log -b html . _build/html py37 create: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37 py37 installdeps: pytest, pytest-rerunfailures, pytest-timeout, pytest-xdist, pdbpp, requests py37 inst: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/.tmp/package/1/deltachat-1.40.2.dev308+g454271f5.zip py37 installed: apipkg==1.5,attrs==20.2.0,certifi==2020.6.20,cffi==1.14.3,chardet==3.0.4,deltachat==1.40.2.dev308+g454271f5,execnet==1.7.1,fancycompleter==0.9.1,idna==2.10,IMAPClient==2.1.0,importlib-metadata==2.0.0,iniconfig==1.0.1,packaging==20.4,pdbpp==0.10.2,pluggy==0.13.1,py==1.9.0,pycparser==2.20,Pygments==2.7.1,pyparsing==2.4.7,pyrepl==0.9.0,pytest==6.1.0,pytest-forked==1.3.0,pytest-rerunfailures==9.1.1,pytest-timeout==1.4.2,pytest-xdist==2.1.0,requests==2.24.0,six==1.15.0,toml==0.10.1,urllib3==1.25.10,wmctrl==0.3,zipp==3.2.0 py37 run-test-pre: PYTHONHASHSEED='558905713' py37 run-test: commands[0] | pytest -n6 --reruns 2 --reruns-delay 5 -v -rsXx --ignored --strict-tls tests examples ============================= test session starts ============================== platform linux -- Python 3.7.5, pytest-6.1.0, py-1.9.0, pluggy-0.13.1 -- /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python cachedir: .tox/py37/.pytest_cache Deltachat core=v1.46.0 sqlite=3.33.0 journal_mode=wal Liveconfig provider: https://testrun.org/new_email? rootdir: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python, configfile: tox.ini plugins: deltachat-1.40.2.dev308+g454271f5, forked-1.3.0, rerunfailures-9.1.1, timeout-1.4.2, xdist-2.1.0 timeout: 90.0s timeout method: thread timeout func_only: False gw0 I / gw1 I / gw2 I / gw3 I / gw4 I / gw5 I [gw0] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw1] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw2] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw3] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw4] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw5] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw0] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw1] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw2] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw4] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw3] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw5] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] gw0 [116] / gw1 [116] / gw2 [116] / gw3 [116] / gw4 [116] / gw5 [116] scheduling tests via LoadScheduling tests/test_account.py::test_parse_system_add_remove[Member Me (tmp1@x.org) removed by tmp2@x.org.-res0] [gw0] [ 0%] PASSED tests/test_account.py::test_parse_system_add_remove[Member Me (tmp1@x.org) removed by tmp2@x.org.-res0] tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by tmp2@x.org.-res1] [gw1] [ 1%] PASSED tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by tmp2@x.org.-res1] tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by me-res3] [gw4] [ 2%] PASSED tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by me-res3] tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by Another member (tmp2@x.org).-res2] [gw2] [ 3%] PASSED tests/test_account.py::test_parse_system_add_remove[Member With space (tmp1@x.org) removed by Another member (tmp2@x.org).-res2] tests/test_account.py::test_parse_system_add_remove[Group left by tmp1@x.org.-res5] [gw5] [ 4%] PASSED tests/test_account.py::test_parse_system_add_remove[Group left by tmp1@x.org.-res5] tests/test_account.py::test_parse_system_add_remove[Group left by some one (tmp1@x.org).-res4] [gw3] [ 5%] PASSED tests/test_account.py::test_parse_system_add_remove[Group left by some one (tmp1@x.org).-res4] tests/test_account.py::test_parse_system_add_remove[Member tmp1@x.org added by tmp2@x.org.-res6] [gw0] [ 6%] PASSED tests/test_account.py::test_parse_system_add_remove[Member tmp1@x.org added by tmp2@x.org.-res6] tests/test_account.py::test_parse_system_add_remove[Member nothing bla bla-None] [gw1] [ 6%] PASSED tests/test_account.py::test_parse_system_add_remove[Member nothing bla bla-None] tests/test_account.py::TestOfflineAccountBasic::test_wrong_db tests/test_account.py::TestOfflineAccountBasic::test_getinfo tests/test_account.py::TestOfflineAccountBasic::test_preconfigure_keypair tests/test_account.py::TestOfflineAccountBasic::test_os_name tests/test_account.py::test_parse_system_add_remove[Another unknown system message-None] [gw2] [ 7%] PASSED tests/test_account.py::test_parse_system_add_remove[Another unknown system message-None] tests/test_account.py::TestOfflineAccountBasic::test_is_not_configured tests/test_account.py::TestOfflineAccountBasic::test_wrong_config_keys [gw4] [ 8%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_wrong_db tests/test_account.py::TestOfflineAccountBasic::test_has_savemime [gw1] [ 9%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_is_not_configured tests/test_account.py::TestOfflineAccountBasic::test_get_config_fails [gw0] [ 10%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_getinfo [gw5] [ 11%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_preconfigure_keypair [gw3] [ 12%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_os_name [gw2] [ 12%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_wrong_config_keys tests/test_account.py::TestOfflineAccountBasic::test_selfcontact_configured tests/test_account.py::TestOfflineAccountBasic::test_selfcontact_if_unconfigured tests/test_account.py::TestOfflineAccountBasic::test_empty_group_bcc_self_enabled tests/test_account.py::TestOfflineAccountBasic::test_has_bccself [gw4] [ 13%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_has_savemime tests/test_account.py::TestOfflineAccountBasic::test_empty_group_bcc_self_disabled [gw1] [ 14%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_get_config_fails [gw3] [ 15%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_has_bccself tests/test_account.py::TestOfflineContact::test_get_contacts_and_delete_fails tests/test_account.py::TestOfflineContact::test_contact_attr [gw5] [ 16%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_selfcontact_if_unconfigured tests/test_account.py::TestOfflineContact::test_create_self_contact [gw0] [ 17%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_selfcontact_configured tests/test_account.py::TestOfflineContact::test_get_contacts_and_delete [gw3] [ 18%] PASSED tests/test_account.py::TestOfflineContact::test_contact_attr [gw2] [ 18%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_empty_group_bcc_self_enabled [gw5] [ 19%] PASSED tests/test_account.py::TestOfflineContact::test_create_self_contact [gw4] [ 20%] PASSED tests/test_account.py::TestOfflineAccountBasic::test_empty_group_bcc_self_disabled tests/test_account.py::TestOfflineChat::test_display tests/test_account.py::TestOfflineChat::test_group_chat_qr[True] tests/test_account.py::TestOfflineContact::test_create_chat_flexibility tests/test_account.py::TestOfflineContact::test_contact_rename [gw1] [ 21%] PASSED tests/test_account.py::TestOfflineContact::test_get_contacts_and_delete_fails tests/test_account.py::TestOfflineChat::test_is_group [gw0] [ 22%] PASSED tests/test_account.py::TestOfflineContact::test_get_contacts_and_delete tests/test_account.py::TestOfflineChat::test_prepare_message_and_send [gw3] [ 23%] PASSED tests/test_account.py::TestOfflineChat::test_display tests/test_account.py::TestOfflineChat::test_message_file[None-application/octet-stream] [gw4] [ 24%] PASSED tests/test_account.py::TestOfflineContact::test_contact_rename tests/test_account.py::TestOfflineChat::test_ac_setup_message_fails [gw1] [ 25%] PASSED tests/test_account.py::TestOfflineChat::test_is_group tests/test_account.py::TestOfflineChat::test_chat_by_id [gw0] [ 25%] PASSED tests/test_account.py::TestOfflineChat::test_prepare_message_and_send tests/test_account.py::TestOfflineChat::test_prepare_file [gw4] [ 26%] PASSED tests/test_account.py::TestOfflineChat::test_ac_setup_message_fails tests/test_account.py::TestOfflineChat::test_set_get_draft [gw1] [ 27%] PASSED tests/test_account.py::TestOfflineChat::test_chat_by_id [gw5] [ 28%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_qr[True] [gw2] [ 29%] PASSED tests/test_account.py::TestOfflineContact::test_create_chat_flexibility tests/test_account.py::TestOfflineChat::test_chat_idempotent tests/test_account.py::TestOfflineChat::test_group_chat_qr[False] tests/test_account.py::TestOfflineChat::test_create_chat_simple [gw3] [ 30%] PASSED tests/test_account.py::TestOfflineChat::test_message_file[None-application/octet-stream] tests/test_account.py::TestOfflineChat::test_message_file[text/plain-text/plain] [gw0] [ 31%] PASSED tests/test_account.py::TestOfflineChat::test_prepare_file tests/test_account.py::TestOfflineChat::test_message_eq_contains [gw4] [ 31%] PASSED tests/test_account.py::TestOfflineChat::test_set_get_draft tests/test_account.py::TestOfflineChat::test_qr_setup_contact [gw2] [ 32%] PASSED tests/test_account.py::TestOfflineChat::test_create_chat_simple [gw1] [ 33%] PASSED tests/test_account.py::TestOfflineChat::test_chat_idempotent tests/test_account.py::TestOfflineChat::test_chat_message_distinctions tests/test_account.py::TestOfflineChat::test_group_chat_add_second_account [gw3] [ 34%] PASSED tests/test_account.py::TestOfflineChat::test_message_file[text/plain-text/plain] tests/test_account.py::TestOfflineChat::test_message_file[image/png-image/png] [gw0] [ 35%] PASSED tests/test_account.py::TestOfflineChat::test_message_eq_contains tests/test_account.py::TestOfflineChat::test_message_send_text [gw2] [ 36%] PASSED tests/test_account.py::TestOfflineChat::test_chat_message_distinctions [gw5] [ 37%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_qr[False] tests/test_account.py::TestOfflineChat::test_get_set_profile_image_simple tests/test_account.py::TestOfflineChat::test_set_config_after_configure_is_forbidden [gw3] [ 37%] PASSED tests/test_account.py::TestOfflineChat::test_message_file[image/png-image/png] tests/test_account.py::TestOfflineChat::test_create_contact [gw0] [ 38%] PASSED tests/test_account.py::TestOfflineChat::test_message_send_text [gw4] [ 39%] PASSED tests/test_account.py::TestOfflineChat::test_qr_setup_contact tests/test_account.py::TestOfflineChat::test_message_image [gw2] [ 40%] PASSED tests/test_account.py::TestOfflineChat::test_set_config_after_configure_is_forbidden tests/test_account.py::TestOfflineChat::test_group_chat_many_members_add_remove tests/test_account.py::TestOfflineChat::test_import_export_one_contact [gw1] [ 41%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_add_second_account tests/test_account.py::TestOfflineChat::test_group_chat_creation [gw5] [ 42%] PASSED tests/test_account.py::TestOfflineChat::test_get_set_profile_image_simple tests/test_account.py::TestOfflineChat::test_mute [gw3] [ 43%] PASSED tests/test_account.py::TestOfflineChat::test_create_contact tests/test_account.py::test_basic_imap_api [gw0] [ 43%] PASSED tests/test_account.py::TestOfflineChat::test_message_image tests/test_account.py::TestOnlineAccount::test_send_file_html_attachment [gw1] [ 44%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_creation tests/test_account.py::TestOfflineChat::test_group_chat_creation_with_translation [gw5] [ 45%] PASSED tests/test_account.py::TestOfflineChat::test_mute tests/test_account.py::TestOfflineChat::test_delete_and_send_fails [gw1] [ 46%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_creation_with_translation tests/test_account.py::TestOnlineAccount::test_send_self_message [gw2] [ 47%] PASSED tests/test_account.py::TestOfflineChat::test_import_export_one_contact tests/test_account.py::TestOnlineAccount::test_move_works_on_self_sent [gw5] [ 48%] PASSED tests/test_account.py::TestOfflineChat::test_delete_and_send_fails tests/test_account.py::TestOnlineAccount::test_mdn_asymetric [gw4] [ 49%] PASSED tests/test_account.py::TestOfflineChat::test_group_chat_many_members_add_remove tests/test_account.py::TestOnlineAccount::test_export_import_self_keys [gw1] [ 50%] PASSED tests/test_account.py::TestOnlineAccount::test_send_self_message tests/test_account.py::TestOnlineAccount::test_send_and_receive_message_markseen [gw0] [ 50%] PASSED tests/test_account.py::TestOnlineAccount::test_send_file_html_attachment [gw4] [ 51%] PASSED tests/test_account.py::TestOnlineAccount::test_export_import_self_keys tests/test_account.py::TestOnlineAccount::test_one_account_send_bcc_setting tests/test_account.py::TestOnlineAccount::test_mvbox_sentbox_threads [gw2] [ 52%] PASSED tests/test_account.py::TestOnlineAccount::test_move_works_on_self_sent tests/test_account.py::TestOnlineAccount::test_forward_messages [gw5] [ 53%] PASSED tests/test_account.py::TestOnlineAccount::test_mdn_asymetric tests/test_account.py::TestOnlineAccount::test_send_and_receive_will_encrypt_decrypt [gw0] [ 54%] PASSED tests/test_account.py::TestOnlineAccount::test_mvbox_sentbox_threads tests/test_account.py::TestOnlineAccount::test_move_works [gw4] [ 55%] PASSED tests/test_account.py::TestOnlineAccount::test_one_account_send_bcc_setting tests/test_account.py::TestOnlineAccount::test_send_file_twice_unicode_filename_mangling [gw2] [ 56%] PASSED tests/test_account.py::TestOnlineAccount::test_forward_messages tests/test_account.py::TestOnlineAccount::test_forward_own_message [gw1] [ 56%] PASSED tests/test_account.py::TestOnlineAccount::test_send_and_receive_message_markseen tests/test_account.py::TestOnlineAccount::test_send_first_message_as_long_unicode_with_cr [gw0] [ 57%] PASSED tests/test_account.py::TestOnlineAccount::test_move_works tests/test_account.py::TestOnlineAccount::test_send_mark_seen_clean_incoming_events [gw4] [ 58%] PASSED tests/test_account.py::TestOnlineAccount::test_send_file_twice_unicode_filename_mangling tests/test_account.py::TestOnlineAccount::test_import_export_online_all [gw2] [ 59%] PASSED tests/test_account.py::TestOnlineAccount::test_forward_own_message tests/test_account.py::TestOnlineAccount::test_ac_setup_message_twice [gw1] [ 60%] PASSED tests/test_account.py::TestOnlineAccount::test_send_first_message_as_long_unicode_with_cr tests/test_account.py::TestOnlineAccount::test_prefer_encrypt [gw4] [ 61%] PASSED tests/test_account.py::TestOnlineAccount::test_import_export_online_all tests/test_account.py::TestOnlineAccount::test_ac_setup_message [gw0] [ 62%] PASSED tests/test_account.py::TestOnlineAccount::test_send_mark_seen_clean_incoming_events tests/test_account.py::TestOnlineAccount::test_send_and_receive_image [gw0] [ 62%] PASSED tests/test_account.py::TestOnlineAccount::test_send_and_receive_image tests/test_account.py::TestOnlineAccount::test_set_get_contact_avatar [gw0] [ 63%] PASSED tests/test_account.py::TestOnlineAccount::test_set_get_contact_avatar tests/test_account.py::TestOnlineAccount::test_add_remove_member_remote_events [gw1] [ 64%] PASSED tests/test_account.py::TestOnlineAccount::test_prefer_encrypt tests/test_account.py::TestOnlineAccount::test_qr_join_chat [gw0] [ 65%] PASSED tests/test_account.py::TestOnlineAccount::test_add_remove_member_remote_events tests/test_account.py::TestOnlineAccount::test_system_group_msg_from_blocked_user [gw2] [ 66%] PASSED tests/test_account.py::TestOnlineAccount::test_ac_setup_message_twice tests/test_account.py::TestOnlineAccount::test_qr_setup_contact [gw1] [ 67%] PASSED tests/test_account.py::TestOnlineAccount::test_qr_join_chat tests/test_account.py::TestOnlineAccount::test_set_get_group_image [gw2] [ 68%] PASSED tests/test_account.py::TestOnlineAccount::test_qr_setup_contact tests/test_account.py::TestOnlineAccount::test_undecipherable_group [gw0] [ 68%] PASSED tests/test_account.py::TestOnlineAccount::test_system_group_msg_from_blocked_user tests/test_account.py::TestOnlineAccount::test_send_receive_locations [gw0] [ 69%] PASSED tests/test_account.py::TestOnlineAccount::test_send_receive_locations tests/test_account.py::TestOnlineAccount::test_delete_multiple_messages [gw3] [ 70%] RERUN tests/test_account.py::test_basic_imap_api tests/test_account.py::test_basic_imap_api [gw0] [ 71%] RERUN tests/test_account.py::TestOnlineAccount::test_delete_multiple_messages tests/test_account.py::TestOnlineAccount::test_delete_multiple_messages [gw2] [ 72%] PASSED tests/test_account.py::TestOnlineAccount::test_undecipherable_group tests/test_account.py::TestOnlineAccount::test_ephemeral_timer [gw3] [ 72%] RERUN tests/test_account.py::test_basic_imap_api tests/test_account.py::test_basic_imap_api [gw3] [ 72%] FAILED tests/test_account.py::test_basic_imap_api tests/test_account.py::TestOnlineAccount::test_configure_generate_key [gw0] [ 72%] PASSED tests/test_account.py::TestOnlineAccount::test_delete_multiple_messages tests/test_account.py::TestOnlineAccount::test_configure_error_msgs [gw5] [ 73%] RERUN tests/test_account.py::TestOnlineAccount::test_send_and_receive_will_encrypt_decrypt tests/test_account.py::TestOnlineAccount::test_send_and_receive_will_encrypt_decrypt [gw5] [ 73%] PASSED tests/test_account.py::TestOnlineAccount::test_send_and_receive_will_encrypt_decrypt tests/test_account.py::TestOnlineAccount::test_reply_encrypted [gw0] [ 74%] PASSED tests/test_account.py::TestOnlineAccount::test_configure_error_msgs tests/test_account.py::TestGroupStressTests::test_group_many_members_add_leave_remove [gw2] [ 75%] PASSED tests/test_account.py::TestOnlineAccount::test_ephemeral_timer tests/test_account.py::TestOnlineAccount::test_name_changes [gw5] [ 75%] PASSED tests/test_account.py::TestOnlineAccount::test_reply_encrypted tests/test_account.py::TestOnlineAccount::test_saved_mime_on_received_message [gw5] [ 76%] PASSED tests/test_account.py::TestOnlineAccount::test_saved_mime_on_received_message tests/test_account.py::TestOnlineConfigureFails::test_invalid_user [gw2] [ 77%] XFAIL tests/test_account.py::TestOnlineAccount::test_name_changes tests/test_account.py::TestOnlineConfigureFails::test_invalid_password [gw1] [ 78%] RERUN tests/test_account.py::TestOnlineAccount::test_set_get_group_image tests/test_account.py::TestOnlineAccount::test_set_get_group_image [gw0] [ 79%] PASSED tests/test_account.py::TestGroupStressTests::test_group_many_members_add_leave_remove tests/test_account.py::TestGroupStressTests::test_synchronize_member_list_on_group_rejoin [gw1] [ 79%] PASSED tests/test_account.py::TestOnlineAccount::test_set_get_group_image tests/test_account.py::TestOnlineAccount::test_immediate_autodelete [gw0] [ 80%] PASSED tests/test_account.py::TestGroupStressTests::test_synchronize_member_list_on_group_rejoin tests/test_increation.py::TestOnlineInCreation::test_no_increation_copies_to_blobdir [gw0] [ 81%] PASSED tests/test_increation.py::TestOnlineInCreation::test_no_increation_copies_to_blobdir tests/test_lowlevel.py::test_empty_context [gw0] [ 81%] PASSED tests/test_lowlevel.py::test_empty_context tests/test_lowlevel.py::test_dc_close_events [gw0] [ 82%] PASSED tests/test_lowlevel.py::test_dc_close_events tests/test_lowlevel.py::test_wrong_db [gw0] [ 83%] PASSED tests/test_lowlevel.py::test_wrong_db tests/test_lowlevel.py::test_empty_blobdir [gw0] [ 84%] PASSED tests/test_lowlevel.py::test_empty_blobdir tests/test_lowlevel.py::test_event_defines [gw0] [ 85%] PASSED tests/test_lowlevel.py::test_event_defines tests/test_lowlevel.py::test_sig [gw0] [ 86%] PASSED tests/test_lowlevel.py::test_sig tests/test_lowlevel.py::test_markseen_invalid_message_ids [gw0] [ 87%] PASSED tests/test_lowlevel.py::test_markseen_invalid_message_ids tests/test_lowlevel.py::test_get_special_message_id_returns_empty_message [gw0] [ 87%] PASSED tests/test_lowlevel.py::test_get_special_message_id_returns_empty_message tests/test_lowlevel.py::test_provider_info_none [gw0] [ 88%] PASSED tests/test_lowlevel.py::test_provider_info_none tests/test_lowlevel.py::test_get_info_open [gw0] [ 89%] PASSED tests/test_lowlevel.py::test_get_info_open examples/test_examples.py::test_echo_quit_plugin [gw1] [ 90%] PASSED tests/test_account.py::TestOnlineAccount::test_immediate_autodelete tests/test_increation.py::TestOnlineInCreation::test_forward_increation [gw3] [ 91%] PASSED tests/test_account.py::TestOnlineAccount::test_configure_generate_key tests/test_account.py::TestOnlineAccount::test_configure_canceled [gw3] [ 92%] PASSED tests/test_account.py::TestOnlineAccount::test_configure_canceled [gw1] [ 93%] PASSED tests/test_increation.py::TestOnlineInCreation::test_forward_increation [gw0] [ 93%] PASSED examples/test_examples.py::test_echo_quit_plugin examples/test_examples.py::test_group_tracking_plugin [gw0] [ 94%] PASSED examples/test_examples.py::test_group_tracking_plugin +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Captured stdout ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw4/test_ac_setup_message0/livedb1". 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw4/test_ac_setup_message0/livedb1". 0.16 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.17 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.17 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.17 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.gxazs@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.17 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.gxazs@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.24 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.gxazs@testrun.org ok 0.24 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:528: success: smtp: tmpy.gxazs@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.26 [events-ac2] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw4/test_ac_setup_message0/livedb2". 0.26 [events-ac2] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw4/test_ac_setup_message0/livedb2". 0.26 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=28 data2=None 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.gxazs@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.gxazs@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac2] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.gxazs@testrun.org ok 0.35 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:528: success: smtp: tmpy.gxazs@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.36 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.gxazs@testrun.org, capabilities: ESEARCH ENABLE CONTEXT=SEARCH SASL-IR SORT Imap4rev1 LIST-EXTENDED SPECIAL-USE ESORT URL-PARTIAL SEARCHRES SNIPPET=FUZZY LIST-STATUS IDLE CATENATE CONDSTORE BINARY ID MOVE UNSELECT MULTIAPPEND UIDPLUS I18NLEVEL=1 THREAD=ORDEREDSUBJECT LOGIN-REFERRALS SORT=DISPLAY THREAD=REFS THREAD=REFERENCES NAMESPACE QRESYNC CHILDREN WITHIN LITERAL+ NOTIFY 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.gxazs@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.36 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=72 data2=None 0.40 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.40 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1227: Scanning folder: Name { response: ResponseData { raw: 4096, response: MailboxData(List { flags: ["\\HasNoChildren"], delimiter: Some("/"), name: "INBOX" }) }, inner: InnerName { attributes: [Custom("\\HasNoChildren")], delimiter: Some("/"), name: "INBOX" } } 0.40 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1260: Using "/" as folder-delimiter. 0.40 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1261: sentbox folder is None 0.41 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1319: FINISHED configuring IMAP-folders. 0.46 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:635: uid/validity change: new 2/1601569359 current 0/0 0.46 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=114 data2=None 0.49 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.gxazs@testrun.org, capabilities: ENABLE NOTIFY MOVE SASL-IR ESORT I18NLEVEL=1 LIST-EXTENDED Imap4rev1 CHILDREN BINARY SPECIAL-USE QRESYNC UNSELECT CATENATE NAMESPACE LIST-STATUS CONTEXT=SEARCH IDLE ESEARCH MULTIAPPEND CONDSTORE SNIPPET=FUZZY LOGIN-REFERRALS SORT=DISPLAY ID SEARCHRES THREAD=REFERENCES LITERAL+ UIDPLUS THREAD=ORDEREDSUBJECT URL-PARTIAL SORT THREAD=REFS WITHIN 0.49 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.gxazs@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false 0.50 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=74 data2=None 0.54 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1227: Scanning folder: Name { response: ResponseData { raw: 4096, response: MailboxData(List { flags: ["\\HasNoChildren"], delimiter: Some("/"), name: "INBOX" }) }, inner: InnerName { attributes: [Custom("\\HasNoChildren")], delimiter: Some("/"), name: "INBOX" } } 0.54 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1260: Using "/" as folder-delimiter. 0.54 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1261: sentbox folder is None 0.55 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1319: FINISHED configuring IMAP-folders. 0.56 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=153 data2=None 0.59 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:342: key generation completed 0.59 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 0.59 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 0.59 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 0.59 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 0.60 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=115 data2=None 0.60 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=1000 data2=None 0.60 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': True} 0.60 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:635: uid/validity change: new 2/1601569359 current 0/0 0.70 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=155 data2=None 0.73 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:342: key generation completed 0.73 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 0.74 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 0.74 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 0.74 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 0.74 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=1000 data2=None 0.74 [events-ac2] calling hook name=ac_configure_completed kwargs={'success': True} 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:146: starting IO 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:48: starting inbox loop 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Imap-thread 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:203: starting smtp loop 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started 0.80 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:321: scheduler is running ac1: tmpy.gxazs@testrun.org account was successfully setup 1.00 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.gxazs@testrun.org, capabilities: LIST-STATUS Imap4rev1 ENABLE UIDPLUS MOVE QRESYNC URL-PARTIAL CONTEXT=SEARCH SNIPPET=FUZZY LOGIN-REFERRALS CHILDREN THREAD=ORDEREDSUBJECT MULTIAPPEND NAMESPACE ID I18NLEVEL=1 LITERAL+ SEARCHRES ESEARCH UNSELECT SPECIAL-USE LIST-EXTENDED IDLE NOTIFY THREAD=REFERENCES SORT=DISPLAY WITHIN SORT CONDSTORE ESORT CATENATE THREAD=REFS SASL-IR BINARY 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:146: starting IO 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:48: starting inbox loop 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Imap-thread 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:203: starting smtp loop 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started ac2: tmpy.gxazs@testrun.org account was successfully setup ========== trigger ac setup message and return setupcode ========== 1.01 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:321: scheduler is running 1.11 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:713: 0 mails read from "INBOX". 1.16 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:65: Idle entering wait-on-remote state 1.20 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.gxazs@testrun.org, capabilities: LOGIN-REFERRALS LIST-STATUS NOTIFY I18NLEVEL=1 CONDSTORE CATENATE URL-PARTIAL ID ENABLE CHILDREN THREAD=REFS NAMESPACE QRESYNC BINARY MOVE SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT SEARCHRES CONTEXT=SEARCH SORT=DISPLAY MULTIAPPEND LITERAL+ SASL-IR LIST-EXTENDED ESORT WITHIN SNIPPET=FUZZY SPECIAL-USE IDLE Imap4rev1 UIDPLUS UNSELECT ESEARCH 1.32 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:713: 0 mails read from "INBOX". 1.36 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:65: Idle entering wait-on-remote state 4.59 [events-ac1] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/autocrypt-setup-message.html 4.59 [events-ac1] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/icon-saved-messages.png 4.60 [events-ac1] DC_EVENT_MSGS_CHANGED data1=0 data2=0 4.60 [events-ac1] DC_EVENT_INFO data1=0 data2=src/chat.rs:1431: Attaching "/tmp/pytest-of-ci/pytest-342/popen-gw4/test_ac_setup_message0/livedb1-blobs/autocrypt-setup-message.html" for message type #File. 4.62 [events-ac1] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/Mr.-hvb_v5odct.texqqc_inxd@testrun. 4.62 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:196: saving job for Smtp-thread: Job { job_id: 0, action: SendMsgToSmtp, foreign_id: 10, desired_timestamp: 1601569375, added_timestamp: 1601569375, tries: 0, param: Params { inner: {Recipients: "tmpy.gxazs@testrun.org", File: "$BLOBDIR/Mr.-hvb_v5odct.texqqc_inxd@testrun."} }, pending_error: None } 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1085: interrupt: smtp 4.63 [events-ac1] DC_EVENT_MSGS_CHANGED data1=10 data2=10 4.63 [events-ac1] calling hook name=ac_outgoing_message kwargs={'message': } 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imex.rs:237: Wait for setup message being sent ... 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:228: smtp fake idle - interrupted 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:220: executing smtp job 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:924: Smtp-job #1, action SendMsgToSmtp started... 4.63 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:993: Smtp begin immediate try 0 of job #1, action SendMsgToSmtp 4.69 [events-ac1] DC_EVENT_ERROR_NETWORK data1=0 data2=Could not connect to SMTP testrun.org:587: SMTP: failed to connect: io: operation would block 4.69 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/job.rs:343: SMTP connection failure: ConnectionFailure(Io(Custom { kind: Other, error: Ssl(Error { code: ErrorCode(5), cause: Some(Io(Kind(WouldBlock))) }, X509VerifyResult { code: 0, error: "ok" }) })) 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1016: Finished immediate try 0 of job #1, action SendMsgToSmtp 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp thread increases job #1, action SendMsgToSmtp tries to 1 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:943: Smtp-job #1 not succeeded on try #1, retry in 20 seconds. 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:196: saving job for Smtp-thread: Job { job_id: 1, action: SendMsgToSmtp, foreign_id: 10, desired_timestamp: 1601569395, added_timestamp: 1601569375, tries: 1, param: Params { inner: {Recipients: "tmpy.gxazs@testrun.org", File: "$BLOBDIR/Mr.-hvb_v5odct.texqqc_inxd@testrun."} }, pending_error: None } 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 4.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (140268279867136) ~~~~~~~~~~~~~~~~~~~~~~~ File "/usr/lib/python3.7/threading.py", line 890, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.7/threading.py", line 926, in _bootstrap_inner self.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 164, in run self._inner_run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 172, in _inner_run event = lib.dc_get_next_event(event_emitter) ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (140268296664832) ~~~~~~~~~~~~~~~~~~~~~~~ File "/usr/lib/python3.7/threading.py", line 890, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.7/threading.py", line 926, in _bootstrap_inner self.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 164, in run self._inner_run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 172, in _inner_run event = lib.dc_get_next_event(event_emitter) ~~~~~~~~~~~~~~~~~~~~~ Stack of (140273222792960) ~~~~~~~~~~~~~~~~~~~~~ File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 967, in _thread_receiver msg = Message.from_io(io) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 432, in from_io header = io.read(9) # type 1, channel 4, payload 4 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 400, in read data = self._read(numbytes - len(buf)) ~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (140273256838976) ~~~~~~~~~~~~~~~~~~~~~ File "", line 1, in File "", line 8, in File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1554, in serve SlaveGateway(io=io, id=id, _startcount=2).serve() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1060, in serve self._execpool.integrate_as_primary_thread() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 267, in integrate_as_primary_thread self._perform_spawn(reply) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1084, in executetask do_exec(co, loc) # noqa File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 237, in config.hook.pytest_cmdline_main(config=config) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 306, in pytest_cmdline_main return wrap_session(config, _main) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 257, in wrap_session session.exitstatus = doit(config, session) or 0 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 313, in _main config.hook.pytest_runtestloop(session=session) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 70, in pytest_runtestloop self.run_one_test(torun) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 87, in run_one_test self.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pytest_rerunfailures.py", line 240, in pytest_runtest_protocol reports = runtestprotocol(item, nextitem=nextitem, log=False) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 127, in runtestprotocol reports.append(call_and_report(item, "call", log)) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 216, in call_and_report call = call_runtest_hook(item, when, **kwds) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in call_runtest_hook lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 310, in from_call result = func() # type: Optional[TResult] File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 163, in pytest_runtest_call item.runtest() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 1627, in runtest self.ihook.pytest_pyfunc_call(pyfuncitem=self) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 184, in pytest_pyfunc_call result = testfunction(**testargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/tests/test_account.py", line 1265, in test_ac_setup_message setup_code = ac1.initiate_key_transfer() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/account.py", line 443, in initiate_key_transfer res = lib.dc_initiate_key_transfer(self._dc_context) +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ [gw4] node down: Not properly terminated [gw4] [ 95%] FAILED tests/test_account.py::TestOnlineAccount::test_ac_setup_message +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Captured stdout ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.11 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.11 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.11 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: xtmpy.wea8f@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.11 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: xtmpy.wea8f@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false 0.21 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.31 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=59 data2=None 0.41 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=86 data2=None 0.51 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=112 data2=None 0.61 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=136 data2=None 0.71 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=159 data2=None 0.81 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=181 data2=None 0.91 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=202 data2=None 1.01 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=222 data2=None 1.11 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=241 data2=None 1.21 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=259 data2=None 1.31 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=276 data2=None 1.41 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=292 data2=None 1.51 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=308 data2=None 1.61 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=323 data2=None 1.71 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=336 data2=None 1.81 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=350 data2=None 1.91 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=362 data2=None 2.01 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=374 data2=None 2.11 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=385 data2=None 2.16 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to connect: permanent: 5.7.8 Error: authentication failed: 2.21 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=396 data2=None 2.31 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=406 data2=None 2.41 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=416 data2=None 2.51 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=425 data2=None 2.61 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=434 data2=None 2.71 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=442 data2=None 2.91 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=458 data2=None 3.01 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=465 data2=None 3.11 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=472 data2=None 3.32 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=484 data2=None 3.52 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=496 data2=None 3.62 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=501 data2=None 3.82 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=511 data2=None 4.12 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=523 data2=None 4.32 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=531 data2=None 4.62 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=541 data2=None 5.02 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=552 data2=None 5.42 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=561 data2=None 6.02 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=571 data2=None 6.04 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:253: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. (no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")) 6.04 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 6.04 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 6.04 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: xtmpy.wea8f@testrun.org@testrun.org:143 security=STARTTLS certificate_checks=automatic oauth2=false 6.22 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=584 data2=None 6.42 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=595 data2=None 6.52 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=601 data2=None 6.83 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=615 data2=None 7.03 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=623 data2=None 7.23 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=631 data2=None 7.53 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=641 data2=None 7.93 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=652 data2=None 8.33 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=661 data2=None 8.93 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=671 data2=None 9.74 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=681 data2=None 11.04 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=691 data2=None 12.13 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:253: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. (no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")) 12.13 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 12.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 12.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 12.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults sentbox_watch=0 12.14 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults mvbox_watch=0 12.15 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults mvbox_move=0 12.16 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: “Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")” 12.16 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': False} 12.16 [events-ac1] DC_EVENT_WARNING data1=0 data2=deltachat-ffi/src/lib.rs:3246: Configure failed: Cannot login as "xtmpy.wea8f@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (140036118918912) ~~~~~~~~~~~~~~~~~~~~~~~ File "/usr/lib/python3.7/threading.py", line 890, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.7/threading.py", line 926, in _bootstrap_inner self.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 164, in run self._inner_run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 172, in _inner_run event = lib.dc_get_next_event(event_emitter) ~~~~~~~~~~~~~~~~~~~~~ Stack of (140038394533632) ~~~~~~~~~~~~~~~~~~~~~ File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 967, in _thread_receiver msg = Message.from_io(io) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 432, in from_io header = io.read(9) # type 1, channel 4, payload 4 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 400, in read data = self._read(numbytes - len(buf)) ~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (140038428579648) ~~~~~~~~~~~~~~~~~~~~~ File "", line 1, in File "", line 8, in File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1554, in serve SlaveGateway(io=io, id=id, _startcount=2).serve() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1060, in serve self._execpool.integrate_as_primary_thread() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 267, in integrate_as_primary_thread self._perform_spawn(reply) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1084, in executetask do_exec(co, loc) # noqa File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 237, in config.hook.pytest_cmdline_main(config=config) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 306, in pytest_cmdline_main return wrap_session(config, _main) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 257, in wrap_session session.exitstatus = doit(config, session) or 0 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 313, in _main config.hook.pytest_runtestloop(session=session) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 70, in pytest_runtestloop self.run_one_test(torun) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 87, in run_one_test self.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pytest_rerunfailures.py", line 240, in pytest_runtest_protocol reports = runtestprotocol(item, nextitem=nextitem, log=False) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 127, in runtestprotocol reports.append(call_and_report(item, "call", log)) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 216, in call_and_report call = call_runtest_hook(item, when, **kwds) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in call_runtest_hook lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 310, in from_call result = func() # type: Optional[TResult] File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 163, in pytest_runtest_call item.runtest() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 1627, in runtest self.ihook.pytest_pyfunc_call(pyfuncitem=self) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 184, in pytest_pyfunc_call result = testfunction(**testargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/tests/test_account.py", line 2003, in test_invalid_user configtracker.wait_progress(500) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/tracker.py", line 79, in wait_progress evdata = self._progress.get() File "/usr/lib/python3.7/queue.py", line 170, in get self.not_empty.wait() File "/usr/lib/python3.7/threading.py", line 296, in wait waiter.acquire() +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ replacing crashed worker gw4 [gw6] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw6] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw5] node down: Not properly terminated [gw5] [ 96%] FAILED tests/test_account.py::TestOnlineConfigureFails::test_invalid_user replacing crashed worker gw5 [gw7] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python tests/test_account.py::TestOnlineAccount::test_qr_verified_group_and_chatting +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Captured stdout ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw2/test_invalid_password0/livedb1". 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw2/test_invalid_password0/livedb1". 0.12 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.12 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.12 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.12 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.vgyu8@testrun.org@testrun.org:993 security=SSL certificate_checks=automatic oauth2=false 0.12 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.vgyu8@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.22 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.32 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=59 data2=None 0.42 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=86 data2=None 0.52 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=112 data2=None 0.62 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=136 data2=None 0.72 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=159 data2=None 0.82 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=181 data2=None 0.92 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=202 data2=None 1.03 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=222 data2=None 1.13 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=241 data2=None 1.23 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=259 data2=None 1.33 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=276 data2=None 1.43 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=292 data2=None 1.53 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=308 data2=None 1.63 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=323 data2=None 1.73 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=336 data2=None 1.83 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=350 data2=None 1.93 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=362 data2=None 2.03 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=374 data2=None 2.13 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=385 data2=None 2.23 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=396 data2=None 2.33 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=406 data2=None 2.43 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=416 data2=None 2.53 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=425 data2=None 2.63 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=434 data2=None 2.73 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=442 data2=None 2.94 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=458 data2=None 3.04 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=465 data2=None 3.14 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=472 data2=None 3.34 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=484 data2=None 3.54 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=496 data2=None 3.64 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=501 data2=None 3.84 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=511 data2=None 4.14 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=523 data2=None 4.34 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=531 data2=None 4.64 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=541 data2=None 5.04 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=552 data2=None 5.44 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=561 data2=None 5.77 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:253: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. (no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")) 5.77 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 5.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 5.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.vgyu8@testrun.org@testrun.org:143 security=STARTTLS certificate_checks=automatic oauth2=false 5.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to connect: permanent: 5.7.8 Error: authentication failed: 5.84 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=573 data2=None 6.04 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=586 data2=None 6.14 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=591 data2=None 6.35 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=602 data2=None 6.55 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=612 data2=None 6.85 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=624 data2=None 7.05 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=632 data2=None 7.35 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=642 data2=None 7.75 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=652 data2=None 8.15 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=661 data2=None 8.75 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=672 data2=None 9.55 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=681 data2=None 10.86 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=691 data2=None 11.86 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:253: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. (no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")) 11.86 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 11.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 11.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 11.87 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults sentbox_watch=0 11.88 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults mvbox_watch=0 11.89 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults mvbox_move=0 11.90 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: “Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.")” 11.90 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': False} 11.90 [events-ac1] DC_EVENT_WARNING data1=0 data2=deltachat-ffi/src/lib.rs:3246: Configure failed: Cannot login as "tmpy.vgyu8@testrun.org". Please check if the email address and the password are correct. no response: code: None, info: Some("[AUTHENTICATIONFAILED] Authentication failed.") 62.58 [events-ac2] EVENT THREAD FINISHED ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (140276442064640) ~~~~~~~~~~~~~~~~~~~~~~~ File "/usr/lib/python3.7/threading.py", line 890, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.7/threading.py", line 926, in _bootstrap_inner self.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 164, in run self._inner_run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 172, in _inner_run event = lib.dc_get_next_event(event_emitter) ~~~~~~~~~~~~~~~~~~~~~ Stack of (140278677493504) ~~~~~~~~~~~~~~~~~~~~~ File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 967, in _thread_receiver msg = Message.from_io(io) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 432, in from_io header = io.read(9) # type 1, channel 4, payload 4 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 400, in read data = self._read(numbytes - len(buf)) ~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (140278711539520) ~~~~~~~~~~~~~~~~~~~~~ File "", line 1, in File "", line 8, in File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1554, in serve SlaveGateway(io=io, id=id, _startcount=2).serve() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1060, in serve self._execpool.integrate_as_primary_thread() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 267, in integrate_as_primary_thread self._perform_spawn(reply) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1084, in executetask do_exec(co, loc) # noqa File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 237, in config.hook.pytest_cmdline_main(config=config) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 306, in pytest_cmdline_main return wrap_session(config, _main) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 257, in wrap_session session.exitstatus = doit(config, session) or 0 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 313, in _main config.hook.pytest_runtestloop(session=session) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 70, in pytest_runtestloop self.run_one_test(torun) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 87, in run_one_test self.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pytest_rerunfailures.py", line 240, in pytest_runtest_protocol reports = runtestprotocol(item, nextitem=nextitem, log=False) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 127, in runtestprotocol reports.append(call_and_report(item, "call", log)) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 216, in call_and_report call = call_runtest_hook(item, when, **kwds) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in call_runtest_hook lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 310, in from_call result = func() # type: Optional[TResult] File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 163, in pytest_runtest_call item.runtest() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 1627, in runtest self.ihook.pytest_pyfunc_call(pyfuncitem=self) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 184, in pytest_pyfunc_call result = testfunction(**testargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/tests/test_account.py", line 1995, in test_invalid_password configtracker.wait_progress(500) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/tracker.py", line 79, in wait_progress evdata = self._progress.get() File "/usr/lib/python3.7/queue.py", line 170, in get self.not_empty.wait() File "/usr/lib/python3.7/threading.py", line 296, in wait waiter.acquire() +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ [gw7] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw2] node down: Not properly terminated [gw2] [ 97%] FAILED tests/test_account.py::TestOnlineConfigureFails::test_invalid_password replacing crashed worker gw2 [gw8] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python tests/test_increation.py::TestOnlineInCreation::test_increation_not_blobdir [gw8] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] [gw7] [ 98%] PASSED tests/test_increation.py::TestOnlineInCreation::test_increation_not_blobdir [gw6] [ 99%] PASSED tests/test_account.py::TestOnlineAccount::test_qr_verified_group_and_chatting tests/test_account.py::TestOnlineConfigureFails::test_invalid_domain +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Captured stdout ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 0.07 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw6/test_invalid_domain0/livedb1". 0.07 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw6/test_invalid_domain0/livedb1". 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:478: no offline autoconfig found 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:10: Requesting URL https://autoconfig.testrun.orgx/mail/config-v1.1.xml?emailaddress=tmpy%2Emg2na%40testrun%2Eorgx 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:15: Can't read URL https://autoconfig.testrun.orgx/mail/config-v1.1.xml?emailaddress=tmpy%2Emg2na%40testrun%2Eorgx 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:10: Requesting URL https://testrun.orgx/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=tmpy%2Emg2na%40testrun%2Eorgx 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:15: Can't read URL https://testrun.orgx/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=tmpy%2Emg2na%40testrun%2Eorgx 0.09 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:10: Requesting URL https://testrun.orgx/autodiscover/autodiscover.xml 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:15: Can't read URL https://testrun.orgx/autodiscover/autodiscover.xml 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:10: Requesting URL https://autodiscover.testrun.orgx/autodiscover/autodiscover.xml 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:15: Can't read URL https://autodiscover.testrun.orgx/autodiscover/autodiscover.xml 0.10 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:10: Requesting URL https://autoconfig.thunderbird.net/v1.1/testrun.orgx 0.19 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=17 data2=None 0.29 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=33 data2=None 0.34 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/read_url.rs:15: Can't read URL https://autoconfig.thunderbird.net/v1.1/testrun.orgx 0.34 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.34 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"testrun.orgx\", 587)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@imap.testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"testrun.orgx\", 465)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@smtp.testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("imap.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("imap.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@imap.testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"smtp.testrun.orgx\", 587)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@smtp.testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("imap.testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("imap.testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@mail.testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"smtp.testrun.orgx\", 465)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@mail.testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("mail.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("mail.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx@mail.testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"mail.testrun.orgx\", 587)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx@mail.testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("mail.testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("mail.testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"mail.testrun.orgx\", 465)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"testrun.orgx\", 587)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("testrun.orgx", 993)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@imap.testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"testrun.orgx\", 465)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@smtp.testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("imap.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("imap.testrun.orgx", 143)` 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@imap.testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"smtp.testrun.orgx\", 587)`" } }) 0.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@smtp.testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.36 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("imap.testrun.orgx", 993)` 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("imap.testrun.orgx", 993)` 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@mail.testrun.orgx:143 security=STARTTLS certificate_checks=automatic oauth2=false 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"smtp.testrun.orgx\", 465)`" } }) 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@mail.testrun.orgx:587 security=STARTTLS certificate_checks=automatic oauth2=false 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"mail.testrun.orgx\", 587)`" } }) 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.mg2na@mail.testrun.orgx:465 security=SSL certificate_checks=automatic oauth2=false 0.36 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to setup connection Io(Custom { kind: Other, error: VerboseError { source: Custom { kind: Other, error: "failed to lookup address information: No address associated with hostname" }, message: "could not resolve address `(\"mail.testrun.orgx\", 465)`" } }) 0.37 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("mail.testrun.orgx", 143)` 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("mail.testrun.orgx", 143)` 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.mg2na@mail.testrun.orgx:993 security=SSL certificate_checks=automatic oauth2=false 0.37 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: io: could not resolve address `("mail.testrun.orgx", 993)` 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:497: failure: io: could not resolve address `("mail.testrun.orgx", 993)` 0.37 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: “Could not find your mail server. Please check your internet connection.” 0.37 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': False} 0.37 [events-ac1] DC_EVENT_WARNING data1=0 data2=deltachat-ffi/src/lib.rs:3246: Configure failed: Could not find your mail server. Please check your internet connection. 0.39 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=71 data2=None 0.49 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=108 data2=None 0.59 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=142 data2=None 0.69 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=175 data2=None 0.79 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=206 data2=None 0.89 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=236 data2=None 0.99 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=264 data2=None 1.09 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=291 data2=None 1.19 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=317 data2=None 1.29 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=341 data2=None 1.39 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=364 data2=None 1.50 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=386 data2=None 1.60 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=406 data2=None 1.70 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=426 data2=None 1.80 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=445 data2=None 1.90 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=463 data2=None 2.00 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=479 data2=None 2.10 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=496 data2=None 2.20 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=511 data2=None 2.30 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=525 data2=None 2.40 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=539 data2=None 2.50 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=552 data2=None 2.60 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=565 data2=None 2.70 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=576 data2=None 2.80 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=588 data2=None 2.90 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=598 data2=None 3.00 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=608 data2=None 3.10 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=618 data2=None 3.20 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=627 data2=None 3.30 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=636 data2=None 3.40 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=644 data2=None 3.50 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=652 data2=None 3.70 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=666 data2=None 3.80 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=673 data2=None 4.00 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=685 data2=None 4.10 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=691 data2=None 4.30 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=702 data2=None 4.50 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=711 data2=None 4.81 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=724 data2=None 5.01 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=732 data2=None 5.31 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=741 data2=None 5.71 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=752 data2=None 6.11 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=761 data2=None 6.71 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=772 data2=None 7.51 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=781 data2=None 8.82 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=791 data2=None ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (140230480885504) ~~~~~~~~~~~~~~~~~~~~~~~ File "/usr/lib/python3.7/threading.py", line 890, in _bootstrap self._bootstrap_inner() File "/usr/lib/python3.7/threading.py", line 926, in _bootstrap_inner self.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 164, in run self._inner_run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/events.py", line 172, in _inner_run event = lib.dc_get_next_event(event_emitter) ~~~~~~~~~~~~~~~~~~~~~ Stack of (140232390915840) ~~~~~~~~~~~~~~~~~~~~~ File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 967, in _thread_receiver msg = Message.from_io(io) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 432, in from_io header = io.read(9) # type 1, channel 4, payload 4 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 400, in read data = self._read(numbytes - len(buf)) ~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (140232424961856) ~~~~~~~~~~~~~~~~~~~~~ File "", line 1, in File "", line 8, in File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1554, in serve SlaveGateway(io=io, id=id, _startcount=2).serve() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1060, in serve self._execpool.integrate_as_primary_thread() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 267, in integrate_as_primary_thread self._perform_spawn(reply) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 285, in _perform_spawn reply.run() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 220, in run self._result = func(*args, **kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/execnet/gateway_base.py", line 1084, in executetask do_exec(co, loc) # noqa File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 237, in config.hook.pytest_cmdline_main(config=config) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 306, in pytest_cmdline_main return wrap_session(config, _main) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 257, in wrap_session session.exitstatus = doit(config, session) or 0 File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/main.py", line 313, in _main config.hook.pytest_runtestloop(session=session) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 73, in pytest_runtestloop self.run_one_test(torun) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/xdist/remote.py", line 87, in run_one_test self.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pytest_rerunfailures.py", line 240, in pytest_runtest_protocol reports = runtestprotocol(item, nextitem=nextitem, log=False) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 127, in runtestprotocol reports.append(call_and_report(item, "call", log)) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 216, in call_and_report call = call_runtest_hook(item, when, **kwds) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in call_runtest_hook lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 310, in from_call result = func() # type: Optional[TResult] File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 256, in lambda: ihook(item=item, **kwds), when=when, reraise=reraise File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/runner.py", line 163, in pytest_runtest_call item.runtest() File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 1627, in runtest self.ihook.pytest_pyfunc_call(pyfuncitem=self) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/hooks.py", line 286, in __call__ return self._hookexec(self, self.get_hookimpls(), kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 93, in _hookexec return self._inner_hookexec(hook, methods, kwargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/manager.py", line 87, in firstresult=hook.spec.opts.get("firstresult") if hook.spec else False, File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/pluggy/callers.py", line 187, in _multicall res = hook_impl.function(*args) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/_pytest/python.py", line 184, in pytest_pyfunc_call result = testfunction(**testargs) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/tests/test_account.py", line 2011, in test_invalid_domain configtracker.wait_progress(500) File "/home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/lib/python3.7/site-packages/deltachat/tracker.py", line 79, in wait_progress evdata = self._progress.get() File "/usr/lib/python3.7/queue.py", line 170, in get self.not_empty.wait() File "/usr/lib/python3.7/threading.py", line 296, in wait waiter.acquire() +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++ [gw6] node down: Not properly terminated [gw6] [100%] FAILED tests/test_account.py::TestOnlineConfigureFails::test_invalid_domain replacing crashed worker gw6 [gw9] linux Python 3.7.5 cwd: /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python [gw9] Python 3.7.5 (default, Nov 7 2019, 10:50:52) -- [GCC 8.3.0] =================================== FAILURES =================================== _____________________________ test_basic_imap_api ______________________________ [gw3] linux -- Python 3.7.5 /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python acfactory = .AccountMaker object at 0x7fef6e0def50> tmpdir = local('/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api2') def test_basic_imap_api(acfactory, tmpdir): > ac1, ac2 = acfactory.get_two_online_accounts() tests/test_account.py:552: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ .tox/py37/lib/python3.7/site-packages/deltachat/testplugin.py:321: in get_two_online_accounts self.wait_configure_and_start_io() .tox/py37/lib/python3.7/site-packages/deltachat/testplugin.py:351: in wait_configure_and_start_io acc._configtracker.wait_finish() _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = def wait_finish(self): """ wait until configure is completed. Raise Exception if Configure failed """ if not self._configure_events.get(): content = "\n".join(map(str, self._ffi_events)) > raise ConfigureFailed(content) E deltachat.tracker.ConfigureFailed: DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to connect: io: operation would block E DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None E DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.7nf9s@testrun.org, capabilities: I18NLEVEL=1 MULTIAPPEND SASL-IR UIDPLUS LIST-STATUS MOVE LITERAL+ ENABLE ESEARCH IDLE SNIPPET=FUZZY SORT CHILDREN CONDSTORE WITHIN URL-PARTIAL QRESYNC UNSELECT CATENATE THREAD=ORDEREDSUBJECT BINARY CONTEXT=SEARCH SORT=DISPLAY LIST-EXTENDED ESORT SEARCHRES Imap4rev1 THREAD=REFERENCES THREAD=REFS SPECIAL-USE ID LOGIN-REFERRALS NAMESPACE NOTIFY E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 E DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 E DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: E E “SMTP: failed to connect: io: operation would block” .tox/py37/lib/python3.7/site-packages/deltachat/tracker.py:90: ConfigureFailed ----------------------------- Captured stdout call ----------------------------- 0.64 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.65 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.65 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.65 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.65 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.74 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.83 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.7nf9s@testrun.org, capabilities: UIDPLUS QRESYNC ESEARCH LOGIN-REFERRALS I18NLEVEL=1 SORT=DISPLAY LIST-EXTENDED NAMESPACE SEARCHRES MOVE ID LITERAL+ BINARY NOTIFY CHILDREN CONDSTORE URL-PARTIAL Imap4rev1 THREAD=REFS IDLE UNSELECT SPECIAL-USE SORT ENABLE SASL-IR CATENATE CONTEXT=SEARCH WITHIN MULTIAPPEND ESORT SNIPPET=FUZZY LIST-STATUS THREAD=ORDEREDSUBJECT THREAD=REFERENCES 0.83 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.84 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.7nf9s@testrun.org ok 0.84 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:528: success: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.85 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=74 data2=None 0.88 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1227: Scanning folder: Name { response: ResponseData { raw: 4096, response: MailboxData(List { flags: ["\\HasNoChildren"], delimiter: Some("/"), name: "INBOX" }) }, inner: InnerName { attributes: [Custom("\\HasNoChildren")], delimiter: Some("/"), name: "INBOX" } } 0.88 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1260: Using "/" as folder-delimiter. 0.88 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1261: sentbox folder is None 0.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1319: FINISHED configuring IMAP-folders. 0.94 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=115 data2=None 1.04 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=155 data2=None 1.07 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:579: Folder "INBOX" is empty. 1.14 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=192 data2=None 1.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:342: key generation completed 1.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 1.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 1.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 1.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 1.21 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=1000 data2=None 1.21 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': True} 2.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 2.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 2.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 2.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 2.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.zsccr@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:146: starting IO 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:48: starting inbox loop 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Imap-thread 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:203: starting smtp loop 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:321: scheduler is running 2.90 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started ac1: tmpy.7nf9s@testrun.org account was successfully setup 3.00 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 3.10 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.zsccr@testrun.org, capabilities: NOTIFY IDLE THREAD=REFS UIDPLUS BINARY SASL-IR SEARCHRES SPECIAL-USE NAMESPACE LIST-STATUS ENABLE CHILDREN QRESYNC SORT THREAD=ORDEREDSUBJECT ID THREAD=REFERENCES CATENATE SORT=DISPLAY LITERAL+ CONTEXT=SEARCH MOVE CONDSTORE URL-PARTIAL LIST-EXTENDED WITHIN LOGIN-REFERRALS I18NLEVEL=1 Imap4rev1 SNIPPET=FUZZY ESORT UNSELECT ESEARCH MULTIAPPEND 3.10 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 3.10 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=59 data2=None 3.10 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.7nf9s@testrun.org, capabilities: CONTEXT=SEARCH MULTIAPPEND URL-PARTIAL NOTIFY THREAD=ORDEREDSUBJECT MOVE I18NLEVEL=1 SNIPPET=FUZZY ESORT SORT LOGIN-REFERRALS CATENATE UIDPLUS ID ENABLE ESEARCH THREAD=REFS SASL-IR UNSELECT LIST-EXTENDED QRESYNC WITHIN LIST-STATUS SPECIAL-USE Imap4rev1 LITERAL+ SEARCHRES SORT=DISPLAY NAMESPACE IDLE CHILDREN CONDSTORE BINARY THREAD=REFERENCES 3.20 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=99 data2=None 3.29 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:713: 0 mails read from "INBOX". 3.30 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=136 data2=None 3.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:65: Idle entering wait-on-remote state 3.39 [events-ac2] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.zsccr@testrun.org ok 3.39 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:528: success: smtp: tmpy.zsccr@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 3.40 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=174 data2=None 3.44 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1227: Scanning folder: Name { response: ResponseData { raw: 4096, response: MailboxData(List { flags: ["\\HasNoChildren"], delimiter: Some("/"), name: "INBOX" }) }, inner: InnerName { attributes: [Custom("\\HasNoChildren")], delimiter: Some("/"), name: "INBOX" } } 3.44 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1260: Using "/" as folder-delimiter. 3.44 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1261: sentbox folder is None 3.45 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1319: FINISHED configuring IMAP-folders. 3.50 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=211 data2=None 3.60 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=245 data2=None 3.70 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=278 data2=None 3.77 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:579: Folder "INBOX" is empty. 3.80 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=310 data2=None 3.90 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=340 data2=None 3.90 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:342: key generation completed 3.90 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 3.91 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 3.91 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 3.91 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 3.92 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=1000 data2=None 3.92 [events-ac2] calling hook name=ac_configure_completed kwargs={'success': True} 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:146: starting IO 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:48: starting inbox loop 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Imap-thread 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:203: starting smtp loop 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread ac2: tmpy.zsccr@testrun.org account was successfully setup 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:321: scheduler is running 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started 4.31 [events-ac2] DC_EVENT_INFO data1=0 data2=src/contact.rs:496: added contact id=10 addr=tmpy.7nf9s@testrun.org 4.31 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0 4.32 [events-ac2] DC_EVENT_MSGS_CHANGED data1=0 data2=0 4.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/contact.rs:496: added contact id=10 addr=tmpy.zsccr@testrun.org 4.33 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0 4.34 [events-ac1] DC_EVENT_MSGS_CHANGED data1=0 data2=0 4.34 [events-ac1] DC_EVENT_INFO data1=0 data2=src/chat.rs:882: [autocrypt] no peerstate for tmpy.zsccr@testrun.org 4.35 [events-ac1] DC_EVENT_INFO data1=0 data2=src/e2ee.rs:95: peerstate for "tmpy.zsccr@testrun.org" missing, cannot encrypt 4.35 [events-ac2] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: async_native_tls: operation would block 4.35 [events-ac2] DC_EVENT_WARNING data1=0 data2=src/scheduler.rs:133: imap connection failed: IMAP Connection Failed with params tmpy.zsccr@testrun.org imap:tmpy.zsccr@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.zsccr@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4: async_native_tls: operation would block 4.35 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:116: IMAP-fake-IDLEing... 4.36 [events-ac1] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/Mr.gutqdix_doc.h9kkv_ygpxr@testrun. 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:196: saving job for Smtp-thread: Job { job_id: 0, action: SendMsgToSmtp, foreign_id: 10, desired_timestamp: 1601569359, added_timestamp: 1601569359, tries: 0, param: Params { inner: {Recipients: "tmpy.zsccr@testrun.org", File: "$BLOBDIR/Mr.gutqdix_doc.h9kkv_ygpxr@testrun."} }, pending_error: None } 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1085: interrupt: smtp 4.37 [events-ac1] DC_EVENT_MSGS_CHANGED data1=10 data2=10 4.37 [events-ac1] calling hook name=ac_outgoing_message kwargs={'message': } 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:228: smtp fake idle - interrupted 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:220: executing smtp job 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:924: Smtp-job #1, action SendMsgToSmtp started... 4.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:993: Smtp begin immediate try 0 of job #1, action SendMsgToSmtp 4.61 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.7nf9s@testrun.org ok 4.96 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=1057 was smtp-sent to tmpy.zsccr@testrun.org 4.96 [events-ac1] DC_EVENT_MSG_DELIVERED data1=10 data2=10 4.96 [events-ac1] calling hook name=ac_message_delivered kwargs={'message': } 4.96 [events-ac1] DC_EVENT_DELETED_BLOB_FILE data1=0 data2=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb1-blobs/Mr.gutqdix_doc.h9kkv_ygpxr@testrun. 4.96 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1016: Finished immediate try 0 of job #1, action SendMsgToSmtp 4.96 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:974: Smtp removes job #1, action SendMsgToSmtp as it succeeded 4.98 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1105: loading job for Smtp-thread 4.98 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:226: smtp fake idle - started --------------------------- Captured stdout teardown --------------------------- ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb1-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb1 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac1 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=1 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 34s USED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:tmpy.7nf9s@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.7nf9s@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- EMPTY FOLDERS: ['INBOX'] ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb2-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb2 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac2 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.zsccr@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=0 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 31s USED_ACCOUNT_SETTINGS=tmpy.zsccr@testrun.org imap:tmpy.zsccr@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.zsccr@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- INBOX 1 messages --------- Message 1 /tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/IMAP/ac2/INBOX/1 Message 1 () Message-Id: 34.60 [MAIN-ac2] stop_ongoing 34.60 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 34.60 [MAIN-ac2] dc_stop_io (stop core IO scheduler) 34.60 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 34.60 [MAIN-ac2] remove dc_context references 34.60 [events-ac2] EVENT THREAD FINISHED 34.61 [MAIN-ac2] wait for event thread to finish 34.61 [MAIN-ac2] shutdown finished 34.61 [MAIN-ac1] stop_ongoing 34.61 [MAIN-ac1] dc_stop_io (stop core IO scheduler) 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:100: shutting down inbox loop 34.62 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:237: shutting down smtp loop 34.62 [MAIN-ac1] remove dc_context references 34.62 [MAIN-ac1] wait for event thread to finish 34.62 [events-ac1] EVENT THREAD FINISHED 34.62 [MAIN-ac1] shutdown finished ----------------------------- Captured stdout call ----------------------------- 0.07 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1". 0.07 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1". 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.14 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.14 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.14 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.14 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.20 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.7nf9s@testrun.org ok 0.20 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:528: success: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.24 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.28 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.28 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.28 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.28 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.28 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.zsccr@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.32 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to connect: io: operation would block 0.33 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.7nf9s@testrun.org, capabilities: CATENATE SPECIAL-USE CONTEXT=SEARCH UIDPLUS THREAD=REFS LIST-EXTENDED SEARCHRES ENABLE LOGIN-REFERRALS NAMESPACE QRESYNC LIST-STATUS SORT=DISPLAY THREAD=ORDEREDSUBJECT SORT UNSELECT MOVE MULTIAPPEND SNIPPET=FUZZY LITERAL+ URL-PARTIAL ID THREAD=REFERENCES WITHIN NOTIFY ESEARCH BINARY ESORT CONDSTORE IDLE SASL-IR CHILDREN I18NLEVEL=1 Imap4rev1 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.34 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=74 data2=None 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1227: Scanning folder: Name { response: ResponseData { raw: 4096, response: MailboxData(List { flags: ["\\HasNoChildren"], delimiter: Some("/"), name: "INBOX" }) }, inner: InnerName { attributes: [Custom("\\HasNoChildren")], delimiter: Some("/"), name: "INBOX" } } 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1260: Using "/" as folder-delimiter. 0.37 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1261: sentbox folder is None 0.38 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.38 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1319: FINISHED configuring IMAP-folders. 0.43 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:579: Folder "INBOX" is empty. 0.44 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=116 data2=None 0.47 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.zsccr@testrun.org, capabilities: THREAD=ORDEREDSUBJECT LIST-EXTENDED CONTEXT=SEARCH WITHIN NOTIFY ID CONDSTORE I18NLEVEL=1 SEARCHRES SASL-IR MOVE CATENATE SPECIAL-USE LOGIN-REFERRALS UIDPLUS THREAD=REFERENCES Imap4rev1 LITERAL+ QRESYNC ENABLE ESORT LIST-STATUS CHILDREN SORT BINARY SORT=DISPLAY SNIPPET=FUZZY ESEARCH IDLE UNSELECT URL-PARTIAL NAMESPACE THREAD=REFS MULTIAPPEND 0.47 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.47 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 0.48 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=71 data2=None 0.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 0.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 0.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 0.48 [events-ac2] DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: “SMTP: failed to connect: io: operation would block” 0.48 [events-ac2] calling hook name=ac_configure_completed kwargs={'success': False} 0.48 [events-ac2] DC_EVENT_WARNING data1=0 data2=deltachat-ffi/src/lib.rs:3246: Configure failed: SMTP: failed to connect: io: operation would block 0.54 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=156 data2=None 0.56 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:342: key generation completed 0.56 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 0.56 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 0.56 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 0.56 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 0.57 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=1000 data2=None 0.57 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': True} ac1: tmpy.7nf9s@testrun.org account was successfully setup 0.74 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:146: starting IO --------------------------- Captured stdout teardown --------------------------- ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac1 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=0 NUMBER_OF_CHATS=0 NUMBER_OF_CONTACTS=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 0s USED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:tmpy.7nf9s@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.7nf9s@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- EMPTY FOLDERS: ['INBOX'] 0.86 [MAIN-ac2] stop_ongoing 0.86 [MAIN-ac2] stop_scheduler called on non-running context 0.86 [MAIN-ac2] remove dc_context references 0.86 [events-ac2] EVENT THREAD FINISHED 0.86 [MAIN-ac2] wait for event thread to finish 0.86 [MAIN-ac2] shutdown finished 0.86 [MAIN-ac1] stop_ongoing 0.86 [MAIN-ac1] dc_stop_io (stop core IO scheduler) 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:100: shutting down inbox loop 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:237: shutting down smtp loop 0.86 [MAIN-ac1] remove dc_context references 0.87 [MAIN-ac1] wait for event thread to finish 0.87 [events-ac1] EVENT THREAD FINISHED 0.87 [MAIN-ac1] shutdown finished ----------------------------- Captured stdout call ----------------------------- 0.06 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api2/livedb1". 0.06 [events-ac1] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api2/livedb1". 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.13 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.7nf9s@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.15 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:522: failure: SMTP: failed to connect: io: operation would block 0.22 [events-ac2] DC_EVENT_INFO data1=0 data2=src/sql.rs:714: First time init: creating tables in "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api2/livedb2". 0.22 [events-ac2] DC_EVENT_INFO data1=0 data2=src/sql.rs:1420: Opened "/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api2/livedb2". 0.23 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=30 data2=None 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:73: Configure ... 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:436: checking internal provider-info for offline autoconfig 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:448: offline autoconfig found 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:494: Trying: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.30 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:519: Trying: smtp: tmpy.zsccr@testrun.org@testrun.org:587 security=STARTTLS certificate_checks=strict oauth2=false 0.33 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.7nf9s@testrun.org, capabilities: I18NLEVEL=1 MULTIAPPEND SASL-IR UIDPLUS LIST-STATUS MOVE LITERAL+ ENABLE ESEARCH IDLE SNIPPET=FUZZY SORT CHILDREN CONDSTORE WITHIN URL-PARTIAL QRESYNC UNSELECT CATENATE THREAD=ORDEREDSUBJECT BINARY CONTEXT=SEARCH SORT=DISPLAY LIST-EXTENDED ESORT SEARCHRES Imap4rev1 THREAD=REFERENCES THREAD=REFS SPECIAL-USE ID LOGIN-REFERRALS NAMESPACE NOTIFY 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.7nf9s@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:83: apply config_defaults bcc_self=1 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults sentbox_watch=0 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_watch=0 0.33 [events-ac1] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:86: skip already set config_defaults mvbox_move=0 0.33 [events-ac1] DC_EVENT_CONFIGURE_PROGRESS data1=0 data2=Error: “SMTP: failed to connect: io: operation would block” 0.33 [events-ac1] calling hook name=ac_configure_completed kwargs={'success': False} --------------------------- Captured stdout teardown --------------------------- ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb1-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb1 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac1 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=1 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 34s USED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:tmpy.7nf9s@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.7nf9s@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- EMPTY FOLDERS: ['INBOX'] ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb2-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/livedb2 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac2 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.zsccr@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=0 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 31s USED_ACCOUNT_SETTINGS=tmpy.zsccr@testrun.org imap:tmpy.zsccr@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.zsccr@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- INBOX 1 messages --------- Message 1 /tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api0/IMAP/ac2/INBOX/1 Message 1 () Message-Id: 34.60 [MAIN-ac2] stop_ongoing 34.60 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 34.60 [MAIN-ac2] dc_stop_io (stop core IO scheduler) 34.60 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 34.60 [MAIN-ac2] remove dc_context references 34.60 [events-ac2] EVENT THREAD FINISHED 34.61 [MAIN-ac2] wait for event thread to finish 34.61 [MAIN-ac2] shutdown finished 34.61 [MAIN-ac1] stop_ongoing 34.61 [MAIN-ac1] dc_stop_io (stop core IO scheduler) 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 34.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:100: shutting down inbox loop 34.62 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:237: shutting down smtp loop 34.62 [MAIN-ac1] remove dc_context references 34.62 [MAIN-ac1] wait for event thread to finish 34.62 [events-ac1] EVENT THREAD FINISHED 34.62 [MAIN-ac1] shutdown finished --------------------------- Captured stdout teardown --------------------------- ARCH=64 BCC_SELF=0 BLOBDIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1-blobs CONFIGURED_MVBOX_FOLDER= CONFIGURED_SENTBOX_FOLDER= DATABASE_DIR=/tmp/pytest-of-ci/pytest-342/popen-gw3/test_basic_imap_api1/livedb1 DATABASE_VERSION=68 DELTACHAT_CORE_VERSION=v1.46.0 DISPLAY_NAME=ac1 E2EE_ENABLED=1 ENTERED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=3 INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 NUMBER_OF_CHAT_MESSAGES=0 NUMBER_OF_CHATS=0 NUMBER_OF_CONTACTS=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 SELFAVATAR= SENTBOX_WATCH=0 SQLITE_VERSION=3.33.0 UPTIME=0h 0m 0s USED_ACCOUNT_SETTINGS=tmpy.7nf9s@testrun.org imap:tmpy.7nf9s@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.7nf9s@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4 --------- EMPTY FOLDERS: ['INBOX'] 0.86 [MAIN-ac2] stop_ongoing 0.86 [MAIN-ac2] stop_scheduler called on non-running context 0.86 [MAIN-ac2] remove dc_context references 0.86 [events-ac2] EVENT THREAD FINISHED 0.86 [MAIN-ac2] wait for event thread to finish 0.86 [MAIN-ac2] shutdown finished 0.86 [MAIN-ac1] stop_ongoing 0.86 [MAIN-ac1] dc_stop_io (stop core IO scheduler) 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:256: No ongoing process to stop. 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:165: stopping IO 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:100: shutting down inbox loop 0.86 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:237: shutting down smtp loop 0.86 [MAIN-ac1] remove dc_context references 0.87 [MAIN-ac1] wait for event thread to finish 0.87 [events-ac1] EVENT THREAD FINISHED 0.87 [MAIN-ac1] shutdown finished --------------------------- Captured stdout teardown --------------------------- 0.49 [MAIN-ac2] stop_ongoing 0.49 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.zsccr@testrun.org, capabilities: SORT SEARCHRES SPECIAL-USE URL-PARTIAL ENABLE THREAD=REFERENCES THREAD=ORDEREDSUBJECT CHILDREN ESEARCH NOTIFY IDLE MOVE SASL-IR CATENATE LIST-STATUS ID NAMESPACE LOGIN-REFERRALS CONTEXT=SEARCH CONDSTORE ESORT Imap4rev1 THREAD=REFS UIDPLUS UNSELECT WITHIN MULTIAPPEND SNIPPET=FUZZY BINARY I18NLEVEL=1 LIST-EXTENDED SORT=DISPLAY QRESYNC LITERAL+ 0.49 [events-ac2] DC_EVENT_INFO data1=0 data2=src/configure/mod.rs:503: success: imap: tmpy.zsccr@testrun.org@testrun.org:993 security=SSL certificate_checks=strict oauth2=false 0.50 [MAIN-ac2] stop_scheduler called on non-running context 0.50 [MAIN-ac2] remove dc_context references 0.50 [MAIN-ac2] wait for event thread to finish 0.50 [events-ac2] EVENT THREAD FINISHED 0.50 [MAIN-ac2] shutdown finished 0.50 [MAIN-ac1] stop_ongoing 0.51 [MAIN-ac1] stop_scheduler called on non-running context 0.51 [MAIN-ac1] remove dc_context references 0.51 [MAIN-ac1] wait for event thread to finish 0.51 [events-ac1] EVENT THREAD FINISHED 0.51 [MAIN-ac1] shutdown finished ____________________________ tests/test_account.py _____________________________ [gw4] linux -- Python 3.7.5 /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python worker 'gw4' crashed while running 'tests/test_account.py::TestOnlineAccount::test_ac_setup_message' ____________________________ tests/test_account.py _____________________________ [gw5] linux -- Python 3.7.5 /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python worker 'gw5' crashed while running 'tests/test_account.py::TestOnlineConfigureFails::test_invalid_user' ____________________________ tests/test_account.py _____________________________ [gw2] linux -- Python 3.7.5 /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python worker 'gw2' crashed while running 'tests/test_account.py::TestOnlineConfigureFails::test_invalid_password' ____________________________ tests/test_account.py _____________________________ [gw6] linux -- Python 3.7.5 /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/python worker 'gw6' crashed while running 'tests/test_account.py::TestOnlineConfigureFails::test_invalid_domain' =========================== short test summary info ============================ XFAIL tests/test_account.py::TestOnlineAccount::test_name_changes reason: Contact was renamed after explicit rename ======== 5 failed, 110 passed, 1 xfailed, 5 rerun in 260.44s (0:04:20) ========= ERROR: InvocationError for command /home/ci/ci_builds/deltachat-core-rust/smooth-progress-bar/remote_tests_python/27395/python/.tox/py37/bin/pytest -n6 --reruns 2 --reruns-delay 5 -v -rsXx --ignored --strict-tls tests examples (exited with code 1) ___________________________________ summary ____________________________________ doc: commands succeeded ERROR: py37: commands failed Exited with code exit status 1 ```

[Hocuri]

Holger just told me that there already is an issue here: https://github.com/async-email/async-native-tls/issues/23

[hpk42]

this is related to https://github.com/async-email/async-native-tls/issues/23 i guess and is not gone with the use of async-std 1.6.5

On Thu, Oct 01, 2020 at 09:40 -0700, Hocuri wrote:

Now this CI failed: https://app.circleci.com/pipelines/github/deltachat/deltachat-core-rust/6700/workflows/d1ec9ee6-98f1-4d02-baca-a6fa7064dc84/jobs/27395.

The log also contained the line 4.35 [events-ac2] DC_EVENT_WARNING data1=0 data2=src/imap/mod.rs:385: try_setup_handle: async_native_tls: operation would block but apparently DC succeeded with another IMAP config later. @dignifiedquire @link2xt do you know anything about this? Even if it's just a timeout we should still try to improve the error message.

-- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/deltachat/deltachat-core-rust/issues/1953#issuecomment-702258975

[link2xt]

Looks like first two connections (SMTP and IMAP) timed out, but since IMAP has two entries for testrun.org in provider database, IMAP did a second attempt.

[link2xt]

Here is a comment saying bug should be fixed by updating async-io from 1.1.4 to 1.1.6: https://github.com/async-email/async-native-tls/issues/23#issuecomment-702336439