test_two_parallel_realtime_simultaneously is flaky

Example of a run that got stuck:

``` ============================= test session starts ============================== platform linux -- Python 3.12.4, pytest-8.2.2, pluggy-1.5.0 rootdir: /home/user/src/deltachat/deltachat-core-rust/deltachat-rpc-client configfile: tox.ini plugins: timeout-2.3.1, deltachat-rpc-client-1.142.1, xdist-3.6.1 timeout: 300.0s timeout method: signal timeout func_only: False collected 1 item tests/test_iroh_webxdc.py::test_two_parallel_realtime_simultaneously -------------------------------- live log call --------------------------------- DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:968: Created new database. Migration done from v68.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:970: Database version: v116.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:298: Opened database "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1b50846-5e7b-4fed-9179-c23552b045be/dc.db".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:111: Configure ...'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:236: checking internal provider-info for offline autoconfig'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:251: offline autoconfig found'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 500} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 550} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 600} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:611: Trying: imap: ci-2vmzp3@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:663: Trying: smtp: ci-2vmzp3@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/icon-saved-messages.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/welcome-image.jpg', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/icon-device.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:968: Created new database. Migration done from v68.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:970: Database version: v116.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:298: Opened database "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1fe478b-65e2-4b60-8b06-317c391eb8c7/dc.db".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:111: Configure ...'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:236: checking internal provider-info for offline autoconfig'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:251: offline autoconfig found'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 500} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 550} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 600} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:611: Trying: imap: ci-vf2434@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:663: Trying: smtp: ci-vf2434@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/icon-saved-messages.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/welcome-image.jpg', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/icon-device.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1b50846-5e7b-4fed-9179-c23552b045be/dc.db-blobs/welcome-image.jpg" for message type #Image.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1fe478b-65e2-4b60-8b06-317c391eb8c7/dc.db-blobs/welcome-image.jpg" for message type #Image.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:635: IMAP success: imap: ci-2vmzp3@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 850} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-vf2434@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:635: IMAP success: imap: ci-vf2434@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 850} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-2vmzp3@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:675: SMTP success: smtp: ci-2vmzp3@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 900} DEBUG root:rpc.py:180 account_id=1 got an event {'key': 'mvbox_move', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=1 got an event {'key': 'show_emails', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-vf2434@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:675: SMTP success: smtp: ci-vf2434@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 900} DEBUG root:rpc.py:180 account_id=2 got an event {'key': 'mvbox_move', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=2 got an event {'key': 'show_emails', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1589: Scanning folder: Name { owner: ResponseData { raw: 4096, response: MailboxData(List { name_attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" }) }, dependent: InnerName { attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" } }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1613: Using "." as folder-delimiter.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "DeltaChat"...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1589: Scanning folder: Name { owner: ResponseData { raw: 4096, response: MailboxData(List { name_attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" }) }, dependent: InnerName { attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" } }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1613: Using "." as folder-delimiter.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "DeltaChat"...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "INBOX.DeltaChat"...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "INBOX.DeltaChat"...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1641: FINISHED configuring IMAP-folders.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1641: FINISHED configuring IMAP-folders.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/select_folder.rs:227: uid/validity change folder INBOX: new 1/1722381350 previous 0/0.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 910} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 920} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/key.rs:253: Generating keypair with type Default'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/select_folder.rs:227: uid/validity change folder INBOX: new 1/1722381350 previous 0/0.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 910} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 920} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/key.rs:253: Generating keypair with type Default'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/key.rs:259: Keypair generated in 0s.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:500: key generation completed'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 940} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:147: skip already set config_defaults mvbox_move=0'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1000} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:66: starting IO'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:389: starting inbox loop'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:745: Starting SMTP loop.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:907: scheduler is running'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/key.rs:259: Keypair generated in 0s.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:500: key generation completed'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 940} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:147: skip already set config_defaults mvbox_move=0'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1000} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:66: starting IO'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:389: starting inbox loop'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:745: Starting SMTP loop.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:907: scheduler is running'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-vf2434@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:817: Start housekeeping...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:856: 3 files in use.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:798: Housekeeping done.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_sentbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_mvbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:817: Start housekeeping...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:856: 3 files in use.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:798: Housekeeping done.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_sentbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_mvbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:771: Done fetching existing messages.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:771: Done fetching existing messages.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1418: Server supports metadata, retrieving server comment and admin contact.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1418: Server supports metadata, retrieving server comment and admin contact.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/scan_folders.rs:31: Starting full folder scan'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/scan_folders.rs:31: Starting full folder scan'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:932: Added contact id=10 addr=ci-vf2434@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:932: Added contact id=10 addr=ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [1].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/chess.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1b50846-5e7b-4fed-9179-c23552b045be/dc.db-blobs/chess.xdc" for message type #Webxdc.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-vf2434@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [1].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgsChanged', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-2vmzp3@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#12 (entry 1) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-vf2434@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#12 (entry 1) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2747 was SMTP-sent to ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2747 was SMTP-sent to ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'MsgDelivered', 'msgId': 12} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [2].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#13 (entry 2) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2751 was SMTP-sent to ci-vf2434@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2751 was SMTP-sent to ci-vf2434@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'MsgDelivered', 'msgId': 12} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 1 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 1 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=98624 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=98624 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(2)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(2)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "2".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 2 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 2 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/chess.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/mimeparser.rs:1325: added blobfile: "$BLOBDIR/chess.xdc"'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.qO-BgiXC1HZ.iCxyS4t39-Y@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#12.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 4s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'IncomingMsg', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-vf2434@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [3].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#14 (entry 3) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-2vmzp3@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/chat.rs:1352: Set gossiped_timestamp for chat Chat#12 to 1722381357.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [2].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#14 (entry 2) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=1492 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=1492 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 14} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/chess-3504196054.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-58/test_two_parallel_realtime_sim0/accounts/f1b50846-5e7b-4fed-9179-c23552b045be/dc.db-blobs/chess-3504196054.xdc" for message type #Webxdc.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-vf2434@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgsChanged', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(3)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(3)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=3451 was SMTP-sent to ci-2vmzp3@nine.testrun.org,ci-vf2434@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=3451 was SMTP-sent to ci-2vmzp3@nine.testrun.org,ci-vf2434@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 14} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "3".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 3 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 3 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.U8F3EQeZQxZ.SQ-pVhVqwkO@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(lhsda5nq7y7nmwkl), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 3s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(4)'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(4)'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "4".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:435: IROH_REALTIME: accepting iroh connection'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [4].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#15 (entry 4) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 4 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.2Z88mb_a2mV.FdbSr-glM7s@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(35xqqsa6gsh3mn2u), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 4s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:435: IROH_REALTIME: accepting iroh connection'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: 35xqqsa6gsh3mn2uojhs4a6u6zbzwcsd7mcgiyuqn4re5ixzpb2a'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: lhsda5nq7y7nmwklo7y7jbm2hquj26pzfvoqd7y7d7kcq3cof4aa'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 4 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=98656 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=98656 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "5".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 5 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 5 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/chess-618958031.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/mimeparser.rs:1325: added blobfile: "$BLOBDIR/chess-618958031.xdc"'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.Xttu6olG7zd.T4U1MaI8cZ6@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#12.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 3s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'IncomingMsg', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-vf2434@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:1352: Set gossiped_timestamp for chat Chat#12 to 1722381358.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-2vmzp3@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [3].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#17 (entry 3) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2827 was SMTP-sent to ci-2vmzp3@nine.testrun.org,ci-vf2434@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2827 was SMTP-sent to ci-2vmzp3@nine.testrun.org,ci-vf2434@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 17} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(6)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 6 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(6)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "6".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 6 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.iesLPQp-wxL.nsjnOyT698G@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(35xqqsa6gsh3mn2u), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: lhsda5nq7y7nmwklo7y7jbm2hquj26pzfvoqd7y7d7kcq3cof4aa'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 3s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:435: IROH_REALTIME: accepting iroh connection'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: 35xqqsa6gsh3mn2uojhs4a6u6zbzwcsd7mcgiyuqn4re5ixzpb2a'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [5].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#17 (entry 5) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=3467 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=3467 was SMTP-sent to ci-vf2434@nine.testrun.org,ci-2vmzp3@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 17} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(7)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(7)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "7".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 7 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 7 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.Pok5GYlqBJD._uf7r-rYVz4@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(lhsda5nq7y7nmwkl), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} ```

Example of a run that finished successfully:

``` ============================= test session starts ============================== platform linux -- Python 3.12.4, pytest-8.2.2, pluggy-1.5.0 rootdir: /home/user/src/deltachat/deltachat-core-rust/deltachat-rpc-client configfile: tox.ini plugins: timeout-2.3.1, deltachat-rpc-client-1.142.1, xdist-3.6.1 timeout: 300.0s timeout method: signal timeout func_only: False collected 1 item tests/test_iroh_webxdc.py::test_two_parallel_realtime_simultaneously -------------------------------- live log call --------------------------------- DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:968: Created new database. Migration done from v68.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:970: Database version: v116.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:298: Opened database "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/029fbdd5-5284-4421-9be0-2c2b4cf8e927/dc.db".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:111: Configure ...'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:236: checking internal provider-info for offline autoconfig'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:251: offline autoconfig found'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 500} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 550} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 600} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:611: Trying: imap: ci-fufwav@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:663: Trying: smtp: ci-fufwav@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/icon-saved-messages.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/welcome-image.jpg', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/icon-device.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:968: Created new database. Migration done from v68.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql/migrations.rs:970: Database version: v116.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:298: Opened database "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/53c4b9e9-5ae5-4f37-9f54-05b8ec90ea08/dc.db".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:111: Configure ...'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 200} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:236: checking internal provider-info for offline autoconfig'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:251: offline autoconfig found'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 500} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 550} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 600} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:611: Trying: imap: ci-hmzhkd@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:663: Trying: smtp: ci-hmzhkd@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/icon-saved-messages.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/welcome-image.jpg', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/icon-device.png', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/029fbdd5-5284-4421-9be0-2c2b4cf8e927/dc.db-blobs/welcome-image.jpg" for message type #Image.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/53c4b9e9-5ae5-4f37-9f54-05b8ec90ea08/dc.db-blobs/welcome-image.jpg" for message type #Image.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 10} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'MsgsChanged', 'msgId': 11} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 11, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:635: IMAP success: imap: ci-fufwav@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 850} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-hmzhkd@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:635: IMAP success: imap: ci-hmzhkd@nine.testrun.org@nine.testrun.org:993 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 850} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-fufwav@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:675: SMTP success: smtp: ci-fufwav@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 900} DEBUG root:rpc.py:180 account_id=1 got an event {'key': 'mvbox_move', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=1 got an event {'key': 'show_emails', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-hmzhkd@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:675: SMTP success: smtp: ci-hmzhkd@nine.testrun.org@nine.testrun.org:465 security=Ssl certificate_checks=strict oauth2=false socks5_config=None.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 900} DEBUG root:rpc.py:180 account_id=2 got an event {'key': 'mvbox_move', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=2 got an event {'key': 'show_emails', 'kind': 'ConfigSynced'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1589: Scanning folder: Name { owner: ResponseData { raw: 4096, response: MailboxData(List { name_attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" }) }, dependent: InnerName { attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" } }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1613: Using "." as folder-delimiter.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "DeltaChat"...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1589: Scanning folder: Name { owner: ResponseData { raw: 4096, response: MailboxData(List { name_attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" }) }, dependent: InnerName { attributes: [Extension("\\\\HasNoChildren")], delimiter: Some("."), name: "INBOX" } }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1613: Using "." as folder-delimiter.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "DeltaChat"...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "INBOX.DeltaChat"...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1539: Looking for MVBOX-folder "INBOX.DeltaChat"...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1641: FINISHED configuring IMAP-folders.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1641: FINISHED configuring IMAP-folders.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/select_folder.rs:227: uid/validity change folder INBOX: new 1/1722381792 previous 0/0.'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 910} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 920} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/key.rs:253: Generating keypair with type Default'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/select_folder.rs:227: uid/validity change folder INBOX: new 1/1722381792 previous 0/0.'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 910} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 920} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/key.rs:253: Generating keypair with type Default'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/key.rs:259: Keypair generated in 0s.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:500: key generation completed'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 940} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/configure.rs:147: skip already set config_defaults mvbox_move=0'} DEBUG root:rpc.py:180 account_id=1 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1000} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:66: starting IO'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:389: starting inbox loop'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:745: Starting SMTP loop.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:907: scheduler is running'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/key.rs:259: Keypair generated in 0s.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:500: key generation completed'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 940} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/configure.rs:147: skip already set config_defaults mvbox_move=0'} DEBUG root:rpc.py:180 account_id=2 got an event {'comment': None, 'kind': 'ConfigureProgress', 'progress': 1000} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:66: starting IO'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:389: starting inbox loop'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:332: Connecting to IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:745: Starting SMTP loop.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:907: scheduler is running'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into [2a01:4f8:241:4ce8::2]:993.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:993 into 116.202.233.236:993.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:375: Logging into IMAP server with LOGIN'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapConnected', 'msg': 'IMAP-LOGIN as ci-hmzhkd@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:391: Successfully logged into IMAP server'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:817: Start housekeeping...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:856: 3 files in use.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/sql.rs:798: Housekeeping done.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_sentbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_mvbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:817: Start housekeeping...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:856: 3 files in use.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/sql.rs:798: Housekeeping done.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_sentbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:2376: Folder configured_mvbox_folder is not configured, skipping fetching contacts from it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:771: Done fetching existing messages.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1418: Server supports metadata, retrieving server comment and admin contact.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:771: Done fetching existing messages.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1418: Server supports metadata, retrieving server comment and admin contact.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/scan_folders.rs:31: Starting full folder scan'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/scan_folders.rs:31: Starting full folder scan'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:932: Added contact id=10 addr=ci-hmzhkd@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:932: Added contact id=10 addr=ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [1].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/chess.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/029fbdd5-5284-4421-9be0-2c2b4cf8e927/dc.db-blobs/chess.xdc" for message type #Webxdc.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-hmzhkd@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [1].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into [2a01:4f8:241:4ce8::2]:465.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/net/dns.rs:85: Resolved nine.testrun.org:465 into 116.202.233.236:465.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgsChanged', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-fufwav@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#12 (entry 1) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpConnected', 'msg': 'SMTP-LOGIN as ci-hmzhkd@nine.testrun.org ok'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#12 (entry 1) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2755 was SMTP-sent to ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2755 was SMTP-sent to ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'MsgDelivered', 'msgId': 12} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [2].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#13 (entry 2) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2739 was SMTP-sent to ci-hmzhkd@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2739 was SMTP-sent to ci-hmzhkd@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'MsgDelivered', 'msgId': 12} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 10, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 1 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 1 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=98624 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=98624 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(2)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(2)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "2".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 2 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 2 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/chess.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/mimeparser.rs:1325: added blobfile: "$BLOBDIR/chess.xdc"'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.fEKbmBG3ceO.VeSOWv-fAod@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#12.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 4s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'IncomingMsg', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-hmzhkd@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [3].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#14 (entry 3) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-fufwav@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/chat.rs:1352: Set gossiped_timestamp for chat Chat#12 to 1722381798.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [2].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#14 (entry 2) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=1492 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=1492 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 14} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 0, 'kind': 'MsgsChanged', 'msgId': 0} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'file': '$BLOBDIR/chess-1285356791.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:2704: Attaching "/tmp/pytest-of-user/pytest-61/test_two_parallel_realtime_sim0/accounts/029fbdd5-5284-4421-9be0-2c2b4cf8e927/dc.db-blobs/chess-1285356791.xdc" for message type #Webxdc.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:77: Peerstate for "ci-hmzhkd@nine.testrun.org" missing, cannot encrypt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgsChanged', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(3)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(3)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=3459 was SMTP-sent to ci-fufwav@nine.testrun.org,ci-hmzhkd@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=3459 was SMTP-sent to ci-fufwav@nine.testrun.org,ci-hmzhkd@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 14} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "3".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [4].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#15 (entry 4) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 3 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 3 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.0wfTTq6ngDe.JT14ItuPjwX@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(bxz3usdce7ify36p), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 4s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=98656 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=98656 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(4)'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(4)'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:435: IROH_REALTIME: accepting iroh connection'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: cakhmt5nm224jm6g43lwdjrhtm42xwyofwy3l7qz4wpqdrex6xyq'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: bxz3usdce7ify36pmiuaihbr6cmtkrv55m3htzth7o4h7hs7a37a'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "4".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(5)'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 4 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 4 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.gjRJ7vyo23r.hEKXIqxJACl@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(cakhmt5nm224jm6g), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 3s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "5".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1661: Need to refetch "INBOX", got unsolicited EXISTS Exists(5)'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 5 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'file': '$BLOBDIR/chess-705926428.xdc', 'kind': 'NewBlobFile'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/mimeparser.rs:1325: added blobfile: "$BLOBDIR/chess-705926428.xdc"'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.1pXpjfQRX4m.6UtTLUluTel@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#12.'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'IncomingMsg', 'msgId': 16} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ChatlistChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 5 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-hmzhkd@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/chat.rs:1352: Set gossiped_timestamp for chat Chat#12 to 1722381800.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:109: IROH_REALTIME: Joining gossip with peers: []'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/e2ee.rs:66: Peerstate for "ci-fufwav@nine.testrun.org" is mutual.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:387: IROH_REALTIME: Sent realtime advertisement'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:812: SMTP fake idle interrupted.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [3].'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#17 (entry 3) over SMTP.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [30], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=2837 was SMTP-sent to ci-fufwav@nine.testrun.org,ci-hmzhkd@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=2837 was SMTP-sent to ci-fufwav@nine.testrun.org,ci-hmzhkd@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 17} DEBUG root:rpc.py:180 account_id=2 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:649: Sending MDNs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:780: SMTP fake idle started.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:808: SMTP has no messages to retry, waiting for interrupt.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(6)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:540: Selected rows from SMTP queue: [5].'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:411: Try number 1 to send message Msg#17 (entry 5) over SMTP.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(6)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "6".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 6 to receive_imf().'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.3hp2y_Z1uQR.szb8CyyDkO5@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(cakhmt5nm224jm6g), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=1 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 3s or interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: bxz3usdce7ify36pmiuaihbr6cmtkrv55m3htzth7o4h7hs7a37a'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'deltachat-jsonrpc/src/api.rs:1831: send_webxdc_realtime_advertisement done'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:479: IROH_REALTIME: NeighborUp: cakhmt5nm224jm6g43lwdjrhtm42xwyofwy3l7qz4wpqdrex6xyq'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp/send.rs:57: Message len=3455 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'SmtpMessageSent', 'msg': 'Message len=3455 was SMTP-sent to ci-hmzhkd@nine.testrun.org,ci-fufwav@nine.testrun.org'} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'MsgDelivered', 'msgId': 17} DEBUG root:rpc.py:180 account_id=1 got an event {'chatId': 12, 'kind': 'ChatlistItemChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/smtp.rs:500: Ratelimiter does not allow sending MDNs now.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:769: smtp got rate limited, waiting for 0h 0m 0s until can send again'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 6 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(7)) }'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:77: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(7)) }'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1237: Starting a full FETCH of message set "7".'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:44: skip idle, got interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1350: Passing message UID 7 to receive_imf().'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1070: Marked messages 7 in folder INBOX as seen.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap.rs:516: No new emails in folder "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:221: Receiving message "Mr.MXfq770z2LE.PRct8fBLppd@localhost", seen=false...'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1445: Adding iroh peer with address NodeAddr { node_id: PublicKey(bxz3usdce7ify36p), info: AddrInfo { relay_url: Some(RelayUrl("https://iroh.testrun.org.:4443/")), direct_addresses: {} } }.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/receive_imf.rs:1675: Message has 1 parts and is assigned to chat #Chat#Trash.'} DEBUG root:rpc.py:180 account_id=2 got an event {'contactId': 10, 'kind': 'ContactsChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/contact.rs:1837: Recently seen loop waiting for 0h 10m 2s or interrupt'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:1392: Successfully received 1 UIDs.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap.rs:718: 1 mails read from "INBOX".'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'IncomingMsgBunch'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ConnectivityChanged'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'ImapInboxIdle'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/scheduler.rs:667: IMAP session supports IDLE, using it.'} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:65: INBOX: Idle entering wait-on-remote state'} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [10], 'kind': 'WebxdcRealtimeData', 'msgId': 13} DEBUG root:rpc.py:180 account_id=2 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=2 got an event {'data': [20], 'kind': 'WebxdcRealtimeData', 'msgId': 16} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} DEBUG root:rpc.py:180 account_id=1 got an event {'data': [40], 'kind': 'WebxdcRealtimeData', 'msgId': 15} DEBUG root:rpc.py:180 account_id=1 got an event {'kind': 'Info', 'msg': 'src/peer_channels.rs:483: IROH_REALTIME: Received realtime data'} PASSED [100%] ------------------------------ live log teardown ------------------------------- DEBUG root:rpc.py:180 account_id=1 got an event {'data': [30], 'kind': 'WebxdcRealtimeData', 'msgId': 13} ============================== 1 passed in 3.90s =============================== ```

deltachat / deltachat-core-rust

test_two_parallel_realtime_simultaneously is flaky #5820