test_transport_synchronization is flaky #7835
Description
Here is the log of the failure:
=================================== FAILURES ===================================
________________________ test_transport_synchronization ________________________
[gw3] darwin -- Python 3.14.2 /Users/runner/work/core/core/deltachat-rpc-client/.tox/py/bin/python
acfactory = <deltachat_rpc_client.pytestplugin.ACFactory object at 0x106ebde10>
log = <deltachat_rpc_client.pytestplugin.log.<locals>.Printer object at 0x1076d9d30>
def test_transport_synchronization(acfactory, log) -> None:
"""Test synchronization of transports between devices."""
ac1, ac2 = acfactory.get_online_accounts(2)
ac1_clone = ac1.clone()
ac1_clone.bring_online()
qr = acfactory.get_account_qr()
ac1.add_transport_from_qr(qr)
ac1_clone.wait_for_event(EventType.TRANSPORTS_MODIFIED)
assert len(ac1.list_transports()) == 2
assert len(ac1_clone.list_transports()) == 2
> ac1_clone.add_transport_from_qr(qr)
tests/test_multitransport.py:202:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
.tox/py/lib/python3.14/site-packages/deltachat_rpc_client/_utils.py:209: in wrapper
return f()
^^^
.tox/py/lib/python3.14/site-packages/deltachat_rpc_client/_utils.py:201: in f
generator.send(res())
^^^^^
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
def rpc_future():
"""Wait for the request to receive a result."""
response = queue.get()
if "error" in response:
> raise JsonRpcError(response["error"])
E deltachat_rpc_client.rpc.JsonRpcError: {'code': -1, 'message': 'cannot configure, already running'}
.tox/py/lib/python3.14/site-packages/deltachat_rpc_client/rpc.py:48: JsonRpcError
------------------------------ Captured log call -------------------------------
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1549: Starting key-contact transition.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1596: Not yet configured, no need to migrate key-contacts'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1252: key-contacts migration took 1.025ms in total.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1538: Created new database. Migration done from v68.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1540: Database version: v145.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:264: Opened database "/private/var/folders/yz/zr09txvs5dn18vt4cn21kzl40000gn/T/pytest-of-runner/pytest-0/popen-gw3/test_transport_synchronization0/accounts/006082a2-1183-462d-b30b-81404536379e/dc.db".'}
DEBUG root:rpc.py:164 account_id=0 got an event {'kind': 'AccountsChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1549: Starting key-contact transition.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1596: Not yet configured, no need to migrate key-contacts'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1252: key-contacts migration took 751µs in total.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1538: Created new database. Migration done from v68.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:1540: Database version: v145.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:264: Opened database "/private/var/folders/yz/zr09txvs5dn18vt4cn21kzl40000gn/T/pytest-of-runner/pytest-0/popen-gw3/test_transport_synchronization0/accounts/37c4ea86-095b-41c5-8280-0118928ca1d5/dc.db".'}
DEBUG root:rpc.py:164 account_id=0 got an event {'kind': 'AccountsChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:265: Configure ...'}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:414: checking internal provider-info for offline autoconfig'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:451: No offline autoconfig found.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:265: Configure ...'}
DEBUG root:rpc.py:164 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1}
DEBUG root:rpc.py:164 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:414: checking internal provider-info for offline autoconfig'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:451: No offline autoconfig found.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/http.rs:363: Not found "https://autoconfig.ci-chatmail.testrun.org/mail/config-v1.1.xml?emailaddress=bnkrwob9t%40ci%2Dchatmail.testrun.org" in cache, fetching.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:140: No memory-cached DNS resolution for autoconfig.ci-chatmail.testrun.org available, waiting for the resolver.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Warning', 'msg': 'src/net/dns.rs:845: DNS resolution for autoconfig.ci-chatmail.testrun.org:443 failed: DNS lookup with memory cache failure: DNS lookup failure: failed to lookup address information: nodename nor servname provided, or not known.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 300}
DEBUG root:rpc.py:164 account_id=2 got an event {'file': '$BLOBDIR/91f9bc261758b09b57844798ebb61f1.jpg', 'kind': 'NewBlobFile'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'file': '$BLOBDIR/91f9bc261758b09b57844798ebb61f1.jpg', 'kind': 'NewBlobFile'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/http.rs:363: Not found "https://ci-chatmail.testrun.org/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=bnkrwob9t%40ci%2Dchatmail.testrun.org" in cache, fetching.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:140: No memory-cached DNS resolution for ci-chatmail.testrun.org available, waiting for the resolver.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/http.rs:363: Not found "https://autoconfig.ci-chatmail.testrun.org/mail/config-v1.1.xml?emailaddress=bvcra9jjf%40ci%2Dchatmail.testrun.org" in cache, fetching.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:140: No memory-cached DNS resolution for autoconfig.ci-chatmail.testrun.org available, waiting for the resolver.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Warning', 'msg': 'src/net/dns.rs:845: DNS resolution for autoconfig.ci-chatmail.testrun.org:443 failed: DNS lookup with memory cache failure: DNS lookup failure: failed to lookup address information: nodename nor servname provided, or not known.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 300}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/http.rs:363: Not found "https://ci-chatmail.testrun.org/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=bvcra9jjf%40ci%2Dchatmail.testrun.org" in cache, fetching.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:140: No memory-cached DNS resolution for ci-chatmail.testrun.org available, waiting for the resolver.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:180: Resolved ci-chatmail.testrun.org into 49.12.217.82.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:180: Resolved ci-chatmail.testrun.org into 49.12.217.82.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2571: Attaching "/private/var/folders/yz/zr09txvs5dn18vt4cn21kzl40000gn/T/pytest-of-runner/pytest-0/popen-gw3/test_transport_synchronization0/accounts/37c4ea86-095b-41c5-8280-0118928ca1d5/dc.db-blobs/91f9bc261758b09b57844798ebb61f1.jpg" for message type #Image.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2571: Attaching "/private/var/folders/yz/zr09txvs5dn18vt4cn21kzl40000gn/T/pytest-of-runner/pytest-0/popen-gw3/test_transport_synchronization0/accounts/006082a2-1183-462d-b30b-81404536379e/dc.db-blobs/91f9bc261758b09b57844798ebb61f1.jpg" for message type #Image.'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11}
DEBUG root:rpc.py:164 account_id=2 got an event {'kind': 'ChatlistChanged'}
DEBUG root:rpc.py:164 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/http.rs:337: Inserting "https://ci-chatmail.testrun.org/.well-known/autoconfig/mail/config-v1.1.xml?emailaddress=bvcra9jjf%40ci%2Dchatmail.testrun.org" into cache.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'file': '$BLOBDIR/b66980bca086b8d0d13cf7e231307fd', 'kind': 'NewBlobFile'}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 500}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 550}
DEBUG root:rpc.py:164 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 600}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:339: Connecting to IMAP server.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:354: IMAP trying to connect to ci-chatmail.testrun.org:993:tls.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:134: Using memory-cached DNS resolution for ci-chatmail.testrun.org.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:180: Resolved ci-chatmail.testrun.org into 49.12.217.82.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/client.rs:122: Attempting IMAP connection to ci-chatmail.testrun.org (49.12.217.82:993).'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:133: SMTP trying to connect to ci-chatmail.testrun.org:465:tls.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:756: SMTP has no messages to retry, waiting for interrupt.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:85: "INBOX": Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/scan_folders.rs:87: Found folders: ["INBOX"].'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:62: IDLE entering wait-on-remote state in folder "INBOX".'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:85: "INBOX": Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:569: No new emails in folder "INBOX".'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:384: IMAP loop iteration for inbox finished, keeping the session.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:597: fetch_new_msg_batch(INBOX): UIDVALIDITY=1770328534, UIDNEXT=1.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:384: IMAP loop iteration for inbox finished, keeping the session.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:597: fetch_new_msg_batch(INBOX): UIDVALIDITY=1770328534, UIDNEXT=1.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ImapInboxIdle'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:598: IMAP session in folder "INBOX" supports IDLE, using it.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1803: Need to refetch "INBOX", got unsolicited EXISTS Exists(1)'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:37: Skipping IDLE in "INBOX" because there may be new mail.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:384: IMAP loop iteration for inbox finished, keeping the session.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:597: fetch_new_msg_batch(INBOX): UIDVALIDITY=1770328538, UIDNEXT=1.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:720: "f25403e0-b09b-4812-8595-29fdf6e2c7f9@localhost" is not a post-message.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1282: Starting UID FETCH of message set "1".'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:792: 1 mails read from "INBOX".'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:801: available_post_msgs: 0, download_later: 0.'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:792: 1 mails read from "INBOX".'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:801: available_post_msgs: 0, download_later: 0.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1372: Passing message UID 1 to receive_imf().'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:536: Receiving message "f25403e0-b09b-4812-8595-29fdf6e2c7f9@localhost", seen=false...'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1208: Chat edit/delete/iroh/sync message (TRASH).'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:2343: Message has 1 parts and is assigned to chat #Chat#Trash.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/sync.rs:307: executing 1 sync item(s)'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'TransportsModified'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1417: Successfully received 1 UIDs.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:204: restarting IO'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:109: stopping IO'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:792: 1 mails read from "INBOX".'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'IncomingMsgBunch'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:767: Shutting down SMTP loop.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/imap.rs:801: available_post_msgs: 0, download_later: 0.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:397: Shutting down inbox loop.'}
DEBUG root:rpc.py:164 account_id=3 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:68: starting IO'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ConnectivityChanged'}
DEBUG root:rpc.py:164 account_id=1 got an event {'kind': 'ImapInboxIdle'}
---------------------------- Captured log teardown -----------------------------
DEBUG root:rpc.py:164 account_id=0 got an event {'kind': 'Info', 'msg': 'src/accounts.rs:353: Stopping IO for all accounts.'}