Test `test_verified_group_vs_delete_server_after` is flaky #5201

link2xt · 2024-01-21T04:38:25Z

Attached is a log from CI:
flaky-test.txt

Maybe similar issue to #5191 but better understand what exactly happened.

iequidoo · 2024-01-23T18:33:47Z

It happened also to me a couple of times, but i didn't understand the reason. In the log it looks like ac2 doesn't receive the vg-member-added message

link2xt · 2024-01-23T18:45:20Z

Maybe this message is delayed and arrives later?

iequidoo · 2024-01-24T02:01:53Z

Apparently it arrives immediately, but we still have some race in IMAP handling:
https://github.com/deltachat/deltachat-core-rust/actions/runs/7630255470/job/20797452090?pr=5209
After IO has been restarted, vg-member-added is received and the debug assertion fired.

iequidoo · 2024-01-29T17:36:39Z

As far as i can tell from the log, there's a race in Session::idle() somewhere between the call to self.server_sent_unsolicited_exists(context) and handle.wait_with_timeout(IDLE_TIMEOUT). So, either it's a problem in async_imap not interrupting the wait_for_timeout() call if new unsolicited responses have arrived or the server implementation not interrupting IMAP IDLE if new emails have arrived just before a receipt of the IDLE command.

…#5201)

link2xt · 2024-06-04T07:43:58Z

Recent log:

2024-06-04T07:40:09.7846720Z =================================== FAILURES ===================================
2024-06-04T07:40:09.7848950Z __________________ test_verified_group_vs_delete_server_after __________________
2024-06-04T07:40:09.7853610Z [gw1] darwin -- Python 3.12.3 /Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/bin/python
2024-06-04T07:40:09.7855390Z 
2024-06-04T07:40:09.7856380Z acfactory = <deltachat.testplugin.ACFactory object at 0x10278de20>
2024-06-04T07:40:09.7858200Z tmp_path = PosixPath('/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0')
2024-06-04T07:40:09.7859930Z lp = <deltachat.testplugin.lp.<locals>.Printer object at 0x1027ef8c0>
2024-06-04T07:40:09.7860530Z 
2024-06-04T07:40:09.7862390Z     def test_verified_group_vs_delete_server_after(acfactory, tmp_path, lp):
2024-06-04T07:40:09.7874750Z         """Test for the issue #4346:
2024-06-04T07:40:09.7906630Z         - User is added to a verified group.
2024-06-04T07:40:09.7907550Z         - First device of the user downloads "member added" from the group.
2024-06-04T07:40:09.7908160Z         - First device removes "member added" from the server.
2024-06-04T07:40:09.7908720Z         - Some new messages are sent to the group.
2024-06-04T07:40:09.7909590Z         - Second device comes online, receives these new messages. The result is a verified group with unverified members.
2024-06-04T07:40:09.7910420Z         - First device re-gossips Autocrypt keys to the group.
2024-06-04T07:40:09.7911030Z         - Now the seconds device has all members verified.
2024-06-04T07:40:09.7911500Z         """
2024-06-04T07:40:09.7911850Z         ac1, ac2 = acfactory.get_online_accounts(2)
2024-06-04T07:40:09.7912420Z         ac2_offl = acfactory.new_online_configuring_account(cloned_from=ac2)
2024-06-04T07:40:09.7912890Z         for ac in [ac2, ac2_offl]:
2024-06-04T07:40:09.7913290Z             ac.set_config("bcc_self", "1")
2024-06-04T07:40:09.7913640Z         ac2.set_config("delete_server_after", "1")
2024-06-04T07:40:09.7914210Z         ac2.set_config("gossip_period", "0")  # Re-gossip in every message
2024-06-04T07:40:09.7914660Z         acfactory.bring_accounts_online()
2024-06-04T07:40:09.7915090Z         dir = tmp_path / "exportdir"
2024-06-04T07:40:09.7915350Z         dir.mkdir()
2024-06-04T07:40:09.7924240Z         ac2.export_self_keys(str(dir))
2024-06-04T07:40:09.7924670Z         ac2_offl.import_self_keys(str(dir))
2024-06-04T07:40:09.7924990Z         ac2_offl.stop_io()
2024-06-04T07:40:09.7925390Z     
2024-06-04T07:40:09.7926020Z         lp.sec("ac1: create verified-group QR, ac2 scans and joins")
2024-06-04T07:40:09.7926520Z         chat1 = ac1.create_group_chat("hello", verified=True)
2024-06-04T07:40:09.7926990Z         assert chat1.is_protected()
2024-06-04T07:40:09.7927390Z         qr = chat1.get_join_qr()
2024-06-04T07:40:09.7927890Z         lp.sec("ac2: start QR-code based join-group protocol")
2024-06-04T07:40:09.7928370Z         chat2 = ac2.qr_join_chat(qr)
2024-06-04T07:40:09.7928760Z         ac1._evtracker.wait_securejoin_inviter_progress(1000)
2024-06-04T07:40:09.7929210Z         # Wait for "Member Me (<addr>) added by <addr>." message.
2024-06-04T07:40:09.7929750Z >       msg_in = ac2._evtracker.wait_next_incoming_message()
2024-06-04T07:40:09.7929990Z 
2024-06-04T07:40:09.7930150Z tests/test_0_complex_or_slow.py:637: 
2024-06-04T07:40:09.7930600Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-06-04T07:40:09.7931270Z .tox/py/lib/python3.12/site-packages/deltachat/events.py:203: in wait_next_incoming_message
2024-06-04T07:40:09.7931840Z     ev = self.get_matching("DC_EVENT_INCOMING_MSG")
2024-06-04T07:40:09.7932440Z .tox/py/lib/python3.12/site-packages/deltachat/events.py:119: in get_matching
2024-06-04T07:40:09.7933030Z     for ev in self.iter_events(timeout=timeout, check_error=check_error):
2024-06-04T07:40:09.7933640Z .tox/py/lib/python3.12/site-packages/deltachat/events.py:115: in iter_events
2024-06-04T07:40:09.7934230Z     yield self.get(timeout=timeout, check_error=check_error)
2024-06-04T07:40:09.7934760Z .tox/py/lib/python3.12/site-packages/deltachat/events.py:108: in get
2024-06-04T07:40:09.7935280Z     ev = self._event_queue.get(timeout=timeout)
2024-06-04T07:40:09.7935810Z /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/queue.py:171: in get
2024-06-04T07:40:09.7936310Z     self.not_empty.wait()
2024-06-04T07:40:09.7936710Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2024-06-04T07:40:09.7936980Z 
2024-06-04T07:40:09.7937220Z self = <Condition(<unlocked _thread.lock object at 0x1032ed280>, 0)>
2024-06-04T07:40:09.7937610Z timeout = None
2024-06-04T07:40:09.7937780Z 
2024-06-04T07:40:09.7937920Z     def wait(self, timeout=None):
2024-06-04T07:40:09.7938270Z         """Wait until notified or until a timeout occurs.
2024-06-04T07:40:09.7939240Z     
2024-06-04T07:40:09.7939630Z         If the calling thread has not acquired the lock when this method is
2024-06-04T07:40:09.7940090Z         called, a RuntimeError is raised.
2024-06-04T07:40:09.7940470Z     
2024-06-04T07:40:09.7940810Z         This method releases the underlying lock, and then blocks until it is
2024-06-04T07:40:09.7941460Z         awakened by a notify() or notify_all() call for the same condition
2024-06-04T07:40:09.7942070Z         variable in another thread, or until the optional timeout occurs. Once
2024-06-04T07:40:09.7942730Z         awakened or timed out, it re-acquires the lock and returns.
2024-06-04T07:40:09.7943160Z     
2024-06-04T07:40:09.7943780Z         When the timeout argument is present and not None, it should be a
2024-06-04T07:40:09.7944320Z         floating point number specifying a timeout for the operation in seconds
2024-06-04T07:40:09.7944830Z         (or fractions thereof).
2024-06-04T07:40:09.7945100Z     
2024-06-04T07:40:09.7945490Z         When the underlying lock is an RLock, it is not released using its
2024-06-04T07:40:09.7946040Z         release() method, since this may not actually unlock the lock when it
2024-06-04T07:40:09.7946600Z         was acquired multiple times recursively. Instead, an internal interface
2024-06-04T07:40:09.7947480Z         of the RLock class is used, which really unlocks it even when it has
2024-06-04T07:40:09.7948110Z         been recursively acquired several times. Another internal interface is
2024-06-04T07:40:09.7949330Z         then used to restore the recursion level when the lock is reacquired.
2024-06-04T07:40:09.7949810Z     
2024-06-04T07:40:09.7950010Z         """
2024-06-04T07:40:09.7950300Z         if not self._is_owned():
2024-06-04T07:40:09.7950790Z             raise RuntimeError("cannot wait on un-acquired lock")
2024-06-04T07:40:09.7951180Z         waiter = _allocate_lock()
2024-06-04T07:40:09.7951530Z         waiter.acquire()
2024-06-04T07:40:09.7951810Z         self._waiters.append(waiter)
2024-06-04T07:40:09.7952140Z         saved_state = self._release_save()
2024-06-04T07:40:09.7952520Z         gotit = False
2024-06-04T07:40:09.7953500Z         try:    # restore state no matter what (e.g., KeyboardInterrupt)
2024-06-04T07:40:09.7955050Z             if timeout is None:
2024-06-04T07:40:09.7955820Z >               waiter.acquire()
2024-06-04T07:40:09.7956610Z E               Failed: Timeout >300.0s
2024-06-04T07:40:09.7957230Z 
2024-06-04T07:40:09.7958090Z /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py:355: Failed
2024-06-04T07:40:09.7959980Z ----------------------------- Captured stdout call -----------------------------
2024-06-04T07:40:09.7963490Z CACHE HIT for ci-ttjgct@***
2024-06-04T07:40:09.7966650Z [acsetup] 0.012 added already configured account <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db> ci-ttjgct@***
2024-06-04T07:40:09.7970450Z CACHE HIT for ci-98hw34@***
2024-06-04T07:40:09.7974040Z [acsetup] 0.023 added already configured account <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db> ci-98hw34@***
2024-06-04T07:40:09.7976690Z bringing accounts online
2024-06-04T07:40:09.7981350Z wait_all_configured finds accounts= {<Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db>: 'CONFIGURED', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db>: 'CONFIGURED'}
2024-06-04T07:40:09.7986100Z 1.88 [events-ac1] INFO src/scheduler.rs:67: starting IO
2024-06-04T07:40:09.7987530Z 1.88 [events-ac1] INFO src/scheduler.rs:389: starting inbox loop
2024-06-04T07:40:09.7988980Z 1.88 [events-ac1] INFO src/imap.rs:333: Connecting to IMAP server
2024-06-04T07:40:09.7992630Z 1.88 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.7994450Z 1.88 [events-ac1] INFO src/scheduler.rs:752: starting smtp loop
2024-06-04T07:40:09.7997670Z 1.88 [events-ac1] INFO src/contact.rs:1841: Recently seen loop waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.7998770Z 1.88 [events-ac1] INFO src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.7999450Z 1.88 [events-ac1] INFO src/scheduler.rs:914: scheduler is running
2024-06-04T07:40:09.8000030Z 1.88 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8000900Z 1.88 [events-ac1] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8001640Z 1.88 [events-ac1] INFO src/smtp.rs:696: Selected rows from SMTP queue: [].
2024-06-04T07:40:09.8002250Z 1.88 [events-ac1] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8002760Z 1.88 [events-ac1] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8003310Z 1.88 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8004030Z ac11.88 [events-ac1] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8004600Z  waiting for inbox IDLE to become ready
2024-06-04T07:40:09.8006440Z 1.89 [events-ac1] INFO src/net.rs:72: Resolved ***:993 into 116.202.233.236:993.
2024-06-04T07:40:09.8007140Z 2.29 [events-ac1] INFO src/imap.rs:412: Logging into IMAP server with LOGIN
2024-06-04T07:40:09.8008900Z 2.60 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as ci-ttjgct@***
2024-06-04T07:40:09.8009540Z 2.60 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8010110Z 2.60 [events-ac1] INFO src/imap.rs:428: Successfully logged into IMAP server
2024-06-04T07:40:09.8010720Z 2.73 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8011440Z 2.73 [events-ac1] INFO src/imap.rs:1448: Server supports metadata, retrieving server comment and admin contact.
2024-06-04T07:40:09.8012160Z 3.14 [events-ac1] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8012690Z 3.14 [events-ac1] INFO src/imap/scan_folders.rs:31: Starting full folder scan
2024-06-04T07:40:09.8013370Z 3.40 [events-ac1] INFO src/imap.rs:552: No new emails in folder "DeltaChat".
2024-06-04T07:40:09.8013960Z 3.54 [events-ac1] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8014510Z 3.67 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8015080Z 3.67 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8015680Z 3.67 [events-ac1] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8016260Z 3.67 [MAIN-ac1] inbox IDLE ready
2024-06-04T07:40:09.8016760Z 3.80 [events-ac1] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8017330Z 5.64 [events-ac2] INFO src/scheduler.rs:67: starting IO
2024-06-04T07:40:09.8018220Z 5.64 [events-ac2] INFO src/scheduler.rs:389: starting inbox loop
2024-06-04T07:40:09.8018990Z 5.64 [events-ac2] INFO src/imap.rs:333: Connecting to IMAP server
2024-06-04T07:40:09.8019530Z 5.64 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8020110Z 5.64 [events-ac2] INFO src/scheduler.rs:752: starting smtp loop
2024-06-04T07:40:09.8020790Z ac25.64 [events-ac2] INFO src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8021640Z 5.64 [events-ac2] INFO src/contact.rs:1841: Recently seen loop waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8022440Z 5.64 [events-ac2] INFO src/scheduler.rs:914: scheduler is running waiting for inbox IDLE to become ready
2024-06-04T07:40:09.8022910Z 
2024-06-04T07:40:09.8023110Z 5.65 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8023930Z 5.65 [events-ac2] INFO src/smtp.rs:696: Selected rows from SMTP queue: [].
2024-06-04T07:40:09.8025510Z 5.65 [events-ac2] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8026290Z 5.65 [events-ac2] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8027160Z 5.65 [events-ac2] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8027730Z 5.65 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8028450Z 5.65 [events-ac2] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8029470Z 5.65 [events-ac2] INFO src/net.rs:72: Resolved ***:993 into 116.202.233.236:993.
2024-06-04T07:40:09.8030150Z 6.06 [events-ac2] INFO src/imap.rs:412: Logging into IMAP server with LOGIN
2024-06-04T07:40:09.8030860Z 6.38 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as ci-98hw34@***
2024-06-04T07:40:09.8031430Z 6.38 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8032040Z 6.38 [events-ac2] INFO src/imap.rs:428: Successfully logged into IMAP server
2024-06-04T07:40:09.8032600Z 6.51 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8033350Z 6.51 [events-ac2] INFO src/imap.rs:1448: Server supports metadata, retrieving server comment and admin contact.
2024-06-04T07:40:09.8034050Z 6.92 [events-ac2] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8034630Z 6.92 [events-ac2] INFO src/imap/scan_folders.rs:31: Starting full folder scan
2024-06-04T07:40:09.8035310Z 7.18 [events-ac2] INFO src/imap.rs:552: No new emails in folder "DeltaChat".
2024-06-04T07:40:09.8036380Z 7.32 [events-ac2] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8036990Z 7.45 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8037430Z 7.45 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8038020Z 7.45 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8038520Z 7.45 [MAIN-ac2] inbox IDLE ready
2024-06-04T07:40:09.8040110Z finished, account2state {<Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db>: 'IDLEREADY', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db>: 'IDLEREADY'}
2024-06-04T07:40:09.8041540Z all accounts online
2024-06-04T07:40:09.8042480Z [acsetup] 7.511 started configure on <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac3/dc.db>
2024-06-04T07:40:09.8043320Z bringing accounts online
2024-06-04T07:40:09.8045920Z wait_all_configured finds accounts= {<Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db>: 'IDLEREADY', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db>: 'IDLEREADY', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac3/dc.db>: 'CONFIGURING'}
2024-06-04T07:40:09.8048190Z 7.58 [events-ac2] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8048840Z 9.96 [events-ac3] INFO src/scheduler.rs:67: starting IO
2024-06-04T07:40:09.8049360Z 9.96 [events-ac3] INFO src/scheduler.rs:389: starting inbox loop
2024-06-04T07:40:09.8049910Z 9.96 [events-ac3] INFO src/imap.rs:333: Connecting to IMAP server
2024-06-04T07:40:09.8050500Z 9.96 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8051030Z 9.96 [events-ac3] INFO src/scheduler.rs:752: starting smtp loop
2024-06-04T07:40:09.8051600Z 9.96 [events-ac3] INFO src/scheduler.rs:914: scheduler is running
2024-06-04T07:40:09.8052110Z 9.96 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8053550Z 9.96 [events-ac3] INFO src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8054450Z 9.96 [events-ac3] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8055030Z ac3 waiting for inbox IDLE to become ready
2024-06-04T07:40:09.8055530Z 9.97 [events-ac3] INFO src/smtp.rs:696: Selected rows from SMTP queue: [].
2024-06-04T07:40:09.8056110Z 9.97 [events-ac3] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8056630Z 9.97 [events-ac3] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8057290Z 9.97 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8057930Z 9.97 [events-ac3] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8060160Z 9.97 [events-ac3] INFO src/net.rs:72: Resolved ***:993 into 116.202.233.236:993.
2024-06-04T07:40:09.8061220Z 9.97 [events-ac3] INFO src/contact.rs:1841: Recently seen loop waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8061970Z 10.36 [events-ac3] INFO src/imap.rs:412: Logging into IMAP server with LOGIN
2024-06-04T07:40:09.8062800Z 10.66 [events-ac3] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as ci-98hw34@***
2024-06-04T07:40:09.8063410Z 10.66 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8063990Z 10.66 [events-ac3] INFO src/imap.rs:428: Successfully logged into IMAP server
2024-06-04T07:40:09.8065600Z 10.78 [events-ac3] INFO src/imap.rs:1619: Scanning folder: Name { owner: ResponseData { raw: 4096, response: MailboxData(List { name_attributes: [Extension("\\HasNoChildren")], delimiter: Some("."), name: "DeltaChat" }) }, dependent: InnerName { attributes: [Extension("\\HasNoChildren")], delimiter: Some("."), name: "DeltaChat" } }
2024-06-04T07:40:09.8068320Z 10.78 [events-ac3] INFO src/imap.rs:1619: 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" } }
2024-06-04T07:40:09.8070700Z 10.78 [events-ac3] INFO src/imap.rs:1643: Using "." as folder-delimiter.
2024-06-04T07:40:09.8071350Z 10.78 [events-ac3] INFO src/imap.rs:1569: Looking for MVBOX-folder "DeltaChat"...
2024-06-04T07:40:09.8072540Z 10.91 [events-ac3] INFO src/imap.rs:1572: MVBOX-folder "DeltaChat" successfully selected, using it.
2024-06-04T07:40:09.8073280Z 11.16 [events-ac3] INFO src/imap.rs:1655: Setting MVBOX FOLDER TO DeltaChat
2024-06-04T07:40:09.8073930Z 11.16 [events-ac3] INFO src/imap.rs:1671: FINISHED configuring IMAP-folders.
2024-06-04T07:40:09.8074560Z 11.29 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8075100Z 11.29 [events-ac3] INFO src/sql.rs:811: Start housekeeping...
2024-06-04T07:40:09.8075580Z 11.29 [events-ac3] INFO src/sql.rs:850: 3 files in use.
2024-06-04T07:40:09.8076040Z 11.29 [events-ac3] INFO src/sql.rs:792: Housekeeping done.
2024-06-04T07:40:09.8076850Z 11.29 [events-ac3] INFO src/imap.rs:2406: Folder configured_sentbox_folder is not configured, skipping fetching contacts from it.
2024-06-04T07:40:09.8077650Z 11.66 [events-ac3] INFO src/imap.rs:804: Done fetching existing messages.
2024-06-04T07:40:09.8079780Z 11.66 [events-ac3] INFO src/imap.rs:1448: Server supports metadata, retrieving server comment and admin contact.
2024-06-04T07:40:09.8082380Z 11.92 [events-ac3] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8084260Z 11.92 [events-ac3] INFO src/imap/scan_folders.rs:31: Starting full folder scan
2024-06-04T07:40:09.8086140Z 12.17 [events-ac3] INFO src/imap.rs:552: No new emails in folder "DeltaChat".
2024-06-04T07:40:09.8088160Z 12.29 [events-ac3] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8088920Z 12.42 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8089560Z 12.42 [events-ac3] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8090940Z 12.42 [events-ac3] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8091510Z 12.42 [MAIN-ac3] inbox IDLE ready
2024-06-04T07:40:09.8093970Z finished, account2state {<Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db>: 'IDLEREADY', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db>: 'IDLEREADY', <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac3/dc.db>: 'IDLEREADY'}
2024-06-04T07:40:09.8096100Z all accounts online
2024-06-04T07:40:09.8096620Z 12.42 [events-ac2] INFO src/scheduler.rs:108: stopping IO
2024-06-04T07:40:09.8097180Z 12.42 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8098940Z 12.42 [events-ac2] INFO src/scheduler.rs:826: shutting down smtp loop
2024-06-04T07:40:09.8100120Z 12.42 [events-ac2] INFO src/scheduler.rs:429: shutting down inbox loop
2024-06-04T07:40:09.8101410Z 12.42 [events-ac2] INFO src/imex.rs:377: Export path: /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir
2024-06-04T07:40:09.8102420Z 12.42 [events-ac2] DC_EVENT_IMEX_PROGRESS data1=10 data2=0
2024-06-04T07:40:09.8103680Z 12.42 [events-ac2] INFO src/imex.rs:748: Exporting key KeyId(db18b18cbcf70487) to /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/public-key-default.asc
2024-06-04T07:40:09.8105900Z 12.42 [events-ac2] DC_EVENT_IMEX_FILE_WRITTEN data1=0 data2=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/public-key-default.asc
2024-06-04T07:40:09.8108350Z 12.42 [events-ac2] INFO src/imex.rs:748: Exporting key KeyId(db18b18cbcf70487) to /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/private-key-default.asc
2024-06-04T07:40:09.8117250Z 12.42 [events-ac2] DC_EVENT_IMEX_FILE_WRITTEN data1=0 data2=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/private-key-default.asc
2024-06-04T07:40:09.8120000Z 12.42 [events-ac2] INFO src/imex.rs:110: IMEX successfully completed
2024-06-04T07:40:09.8120630Z 12.42 [events-ac2] DC_EVENT_IMEX_PROGRESS data1=1000 data2=0
2024-06-04T07:40:09.8121160Z 12.42 [events-ac2] INFO src/scheduler.rs:67: starting IO
2024-06-04T07:40:09.8121730Z 12.43 [events-ac2] INFO src/scheduler.rs:752: starting smtp loop
2024-06-04T07:40:09.8122400Z 12.43 [events-ac2] INFO src/contact.rs:1841: Recently seen loop waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8123290Z 12.43 [events-ac2] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8123970Z 12.43 [events-ac2] INFO src/scheduler.rs:389: starting inbox loop
2024-06-04T07:40:09.8124480Z 12.43 [events-ac2] INFO src/imap.rs:333: Connecting to IMAP server
2024-06-04T07:40:09.8125110Z 12.43 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8125640Z 12.43 [events-ac2] INFO src/scheduler.rs:914: scheduler is running
2024-06-04T07:40:09.8126220Z 12.43 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8126830Z 12.43 [events-ac2] INFO src/smtp.rs:696: Selected rows from SMTP queue: [].
2024-06-04T07:40:09.8127380Z 12.43 [events-ac2] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8127940Z 12.43 [events-ac2] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8128510Z 12.43 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8129130Z 12.43 [events-ac2] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8130920Z 12.43 [events-ac2] INFO src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8132140Z 12.43 [events-ac2] INFO src/net.rs:72: Resolved ***:993 into 116.202.233.236:993.
2024-06-04T07:40:09.8132660Z 12.43 [events-ac3] INFO src/scheduler.rs:108: stopping IO
2024-06-04T07:40:09.8133110Z 12.43 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8133600Z 12.43 [events-ac3] INFO src/scheduler.rs:826: shutting down smtp loop
2024-06-04T07:40:09.8134130Z 12.43 [events-ac3] INFO src/scheduler.rs:429: shutting down inbox loop
2024-06-04T07:40:09.8135130Z 12.43 [events-ac3] INFO src/imex.rs:377: Import path: /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir
2024-06-04T07:40:09.8136020Z 12.43 [events-ac3] DC_EVENT_IMEX_PROGRESS data1=10 data2=0
2024-06-04T07:40:09.8137090Z 12.43 [events-ac3] INFO src/imex.rs:648: Considering key file: /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/public-key-default.asc.
2024-06-04T07:40:09.8138940Z 12.43 [events-ac3] WARNING src/imex.rs:655: Failed to import secret key from /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/public-key-default.asc: rPGP error: no matching packet found.
2024-06-04T07:40:09.8140990Z 12.43 [events-ac3] INFO src/imex.rs:648: Considering key file: /private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/exportdir/private-key-default.asc.
2024-06-04T07:40:09.8142670Z 12.46 [events-ac3] INFO src/imex.rs:323: No Autocrypt-Prefer-Encrypt header.
2024-06-04T07:40:09.8143260Z 12.46 [events-ac3] INFO src/imex.rs:344: stored self key: KeyId(db18b18cbcf70487)
2024-06-04T07:40:09.8143800Z 12.46 [events-ac3] INFO src/imex.rs:110: IMEX successfully completed
2024-06-04T07:40:09.8144270Z 12.46 [events-ac3] DC_EVENT_IMEX_PROGRESS data1=1000 data2=0
2024-06-04T07:40:09.8144690Z 12.46 [events-ac3] INFO src/scheduler.rs:67: starting IO
2024-06-04T07:40:09.8145130Z 12.46 [events-ac3] INFO src/scheduler.rs:752: starting smtp loop
2024-06-04T07:40:09.8145730Z 12.46 [events-ac3] INFO src/contact.rs:1841: Recently seen loop waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8146310Z 12.46 [events-ac3] INFO src/scheduler.rs:389: starting inbox loop
2024-06-04T07:40:09.8146790Z 12.46 [events-ac3] INFO src/imap.rs:333: Connecting to IMAP server
2024-06-04T07:40:09.8147270Z 12.46 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8147910Z 12.46 [events-ac3] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8148650Z 12.46 [events-ac3] INFO src/location.rs:747: Location loop is waiting for 24h 0m 0s or interrupt
2024-06-04T07:40:09.8149120Z 12.46 [MAIN-ac3] stop_ongoing
2024-06-04T07:40:09.8149450Z 12.46 [MAIN-ac3] dc_stop_io (stop core IO scheduler)
2024-06-04T07:40:09.8149880Z 12.46 [events-ac3] INFO src/scheduler.rs:914: scheduler is running
2024-06-04T07:40:09.8150170Z 
2024-06-04T07:40:09.8150380Z ========== ac1: create verified-group QR, ac2 scans and joins ==========
2024-06-04T07:40:09.8150850Z 12.46 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8151350Z 12.46 [events-ac3] INFO src/smtp.rs:696: Selected rows from SMTP queue: [].
2024-06-04T07:40:09.8151830Z 12.46 [events-ac3] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8152290Z 12.46 [events-ac3] INFO src/context.rs:706: No ongoing process to stop.
2024-06-04T07:40:09.8152800Z 12.46 [events-ac3] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8153290Z 12.46 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8153880Z 12.46 [events-ac3] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8154670Z 12.46 [events-ac3] INFO src/scheduler.rs:108: stopping IO
2024-06-04T07:40:09.8155130Z 12.46 [events-ac1] DC_EVENT_MSGS_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8155560Z 12.46 [events-ac1] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8156000Z 12.46 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8156470Z 12.46 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8156970Z 12.46 [events-ac3] INFO src/scheduler.rs:429: shutting down inbox loop
2024-06-04T07:40:09.8157490Z 12.46 [events-ac3] INFO src/scheduler.rs:826: shutting down smtp loop
2024-06-04T07:40:09.8157950Z 12.46 [events-ac1] DC_EVENT_CHAT_MODIFIED data1=12 data2=0
2024-06-04T07:40:09.8158390Z 12.46 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8158960Z 12.46 [events-ac1] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#12 to 0.
2024-06-04T07:40:09.8159490Z 12.46 [events-ac1] DC_EVENT_MSGS_CHANGED data1=12 data2=12
2024-06-04T07:40:09.8171990Z 
2024-06-04T07:40:09.8172530Z ========== ac2: start QR-code based join-group protocol ==========
2024-06-04T07:40:09.8173140Z 12.46 [events-ac1] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8173690Z 12.46 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8174270Z 12.46 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8174810Z 12.46 [events-ac1] DC_EVENT_MSGS_CHANGED data1=12 data2=13
2024-06-04T07:40:09.8176090Z 12.46 [events-ac2] INFO src/contact.rs:936: Added contact id=10 addr=ci-ttjgct@***.
2024-06-04T07:40:09.8176690Z 12.46 [events-ac2] INFO src/securejoin.rs:161: Requesting secure-join ...
2024-06-04T07:40:09.8177220Z 12.46 [events-ac1] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8177820Z 12.46 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8178340Z 12.46 [events-ac1] INFO src/securejoin.rs:126: Generated QR code.
2024-06-04T07:40:09.8178800Z 12.46 [events-ac2] DC_EVENT_MSGS_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8179230Z 12.46 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8179700Z 12.46 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8180560Z 12.46 [events-ac2] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8181430Z 12.46 [events-ac2] INFO src/e2ee.rs:77: Peerstate for "ci-ttjgct@***" missing, cannot encrypt.
2024-06-04T07:40:09.8182220Z 12.46 [events-ac2] INFO src/mimefactory.rs:1115: Sending secure-join message "vg-request".
2024-06-04T07:40:09.8182850Z 12.46 [events-ac2] INFO src/scheduler.rs:819: smtp fake idle - interrupted
2024-06-04T07:40:09.8183420Z 12.46 [events-ac2] INFO src/smtp.rs:696: Selected rows from SMTP queue: [1].
2024-06-04T07:40:09.8183950Z 12.46 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8184800Z 12.46 [events-ac2] INFO src/chat.rs:349: Created group/mailinglist 'hello' grpid=aNsJKWSN4nq as Chat#13, blocked=Not, protected=Unprotected.
2024-06-04T07:40:09.8185570Z 12.46 [events-ac2] DC_EVENT_MSGS_CHANGED data1=13 data2=13
2024-06-04T07:40:09.8186000Z 12.46 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8186480Z 12.46 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8187100Z 12.46 [events-ac2] INFO src/net.rs:72: Resolved ***:465 into 116.202.233.236:465.
2024-06-04T07:40:09.8187690Z 12.84 [events-ac2] INFO src/imap.rs:412: Logging into IMAP server with LOGIN
2024-06-04T07:40:09.8188370Z 13.16 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as ci-98hw34@***
2024-06-04T07:40:09.8188920Z 13.16 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8189450Z 13.16 [events-ac2] INFO src/imap.rs:428: Successfully logged into IMAP server
2024-06-04T07:40:09.8190770Z 13.26 [events-ac2] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as ci-98hw34@*** ok
2024-06-04T07:40:09.8191910Z 13.26 [events-ac2] INFO src/smtp.rs:564: Try number 1 to send message Msg#12 (entry 1) over SMTP
2024-06-04T07:40:09.8192530Z 13.26 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8193430Z 13.29 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8194320Z 13.42 [events-ac2] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8194850Z 13.55 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8195360Z 13.55 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8196300Z 13.55 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8197410Z 13.68 [events-ac2] INFO src/smtp/send.rs:57: Message len=2473 was SMTP-sent to ci-ttjgct@***,ci-98hw34@***.
2024-06-04T07:40:09.8198430Z 13.68 [events-ac2] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=2473 was SMTP-sent to ci-ttjgct@***,ci-98hw34@***
2024-06-04T07:40:09.8199220Z 13.68 [events-ac2] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8199780Z 13.68 [events-ac2] DC_EVENT_MSG_DELIVERED data1=12 data2=12
2024-06-04T07:40:09.8200250Z 13.68 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8200710Z 13.68 [events-ac2] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8201180Z 13.68 [events-ac2] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8201710Z 13.68 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8202770Z 13.68 [events-ac2] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8203710Z 13.74 [events-ac2] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
2024-06-04T07:40:09.8205400Z 13.87 [events-ac1] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
2024-06-04T07:40:09.8206190Z 14.00 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8206690Z 14.12 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8207190Z 14.13 [events-ac2] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8207840Z 14.26 [events-ac1] INFO src/contact.rs:936: Added contact id=10 addr=ci-98hw34@***.
2024-06-04T07:40:09.8208380Z 14.26 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8208940Z 14.26 [events-ac1] INFO src/imap.rs:1267: Starting a full FETCH of message set "14".
2024-06-04T07:40:09.8209700Z 14.26 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8210370Z 14.26 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8210970Z 14.26 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8211540Z 14.26 [events-ac2] INFO src/imap/idle.rs:39: skip idle, got interrupt
2024-06-04T07:40:09.8212040Z 14.39 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8212610Z 14.39 [events-ac1] INFO src/imap.rs:1380: Passing message UID 14 to receive_imf().
2024-06-04T07:40:09.8213390Z 14.40 [events-ac1] INFO src/receive_imf.rs:223: Receiving message "Mr.2Mvxtyyw-Lv.qaaGKcLUWdz@localhost", seen=false...
2024-06-04T07:40:09.8214180Z 14.40 [events-ac1] INFO src/securejoin.rs:293: Received secure-join message "vg-request".
2024-06-04T07:40:09.8214830Z 14.40 [events-ac1] DC_EVENT_SECUREJOIN_INVITER_PROGRESS data1=10 data2=300
2024-06-04T07:40:09.8215550Z 14.40 [events-ac1] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8217440Z 14.40 [events-ac1] INFO src/e2ee.rs:66: Peerstate for "ci-98hw34@***" is mutual.
2024-06-04T07:40:09.8218180Z 14.40 [events-ac1] INFO src/mimefactory.rs:1115: Sending secure-join message "vg-auth-required".
2024-06-04T07:40:09.8219000Z 14.41 [events-ac1] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#13 to 1717486496.
2024-06-04T07:40:09.8219990Z 14.41 [events-ac1] INFO src/scheduler.rs:819: smtp fake idle - interrupted
2024-06-04T07:40:09.8222230Z 14.41 [events-ac1] INFO src/smtp.rs:696: Selected rows from SMTP queue: [1].
2024-06-04T07:40:09.8223500Z 14.41 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8224000Z 14.41 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8224620Z 14.41 [events-ac1] INFO src/contact.rs:1841: Recently seen loop waiting for 0h 9m 59s or interrupt
2024-06-04T07:40:09.8226500Z 14.41 [events-ac1] INFO src/imap.rs:1422: Successfully received 1 UIDs.
2024-06-04T07:40:09.8227070Z 14.41 [events-ac1] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8227550Z 14.41 [events-ac1] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
2024-06-04T07:40:09.8228210Z 14.41 [events-ac1] INFO src/net.rs:72: Resolved ***:465 into 116.202.233.236:465.
2024-06-04T07:40:09.8228760Z 14.52 [events-ac2] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8229380Z 14.54 [events-ac1] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 14 marked as deleted
2024-06-04T07:40:09.8230050Z 14.54 [events-ac1] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8230720Z 14.65 [events-ac2] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 11 marked as deleted
2024-06-04T07:40:09.8231350Z 14.65 [events-ac2] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8231940Z 14.68 [events-ac1] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8232820Z 14.78 [events-ac2] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8233380Z 14.95 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8233880Z 14.95 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8234500Z 14.95 [events-ac1] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8235130Z 15.06 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8235670Z 15.06 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8236260Z 15.06 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8236970Z 15.07 [events-ac1] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8237720Z 15.19 [events-ac2] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8238600Z 15.20 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as ci-ttjgct@*** ok
2024-06-04T07:40:09.8239620Z 15.20 [events-ac1] INFO src/smtp.rs:564: Try number 1 to send message Msg#14 (entry 1) over SMTP
2024-06-04T07:40:09.8240430Z 15.20 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8241220Z 15.62 [events-ac1] INFO src/smtp/send.rs:57: Message len=5358 was SMTP-sent to ci-98hw34@***.
2024-06-04T07:40:09.8242120Z 15.62 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=5358 was SMTP-sent to ci-98hw34@***
2024-06-04T07:40:09.8242830Z 15.62 [events-ac1] DC_EVENT_MSG_DELIVERED data1=13 data2=14
2024-06-04T07:40:09.8243390Z 15.62 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8243910Z 15.62 [events-ac1] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8244420Z 15.63 [events-ac1] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8244920Z 15.63 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8245610Z 15.63 [events-ac1] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8246530Z 15.69 [events-ac2] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
2024-06-04T07:40:09.8247290Z 15.95 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8247840Z 16.08 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8248890Z 16.08 [events-ac2] INFO src/imap.rs:1267: Starting a full FETCH of message set "12".
2024-06-04T07:40:09.8249640Z 16.22 [events-ac2] INFO src/imap.rs:1380: Passing message UID 12 to receive_imf().
2024-06-04T07:40:09.8250500Z 16.25 [events-ac2] INFO src/receive_imf.rs:223: Receiving message "Mr.4ztu_8NjDr6.lZUoxlvX-pZ@localhost", seen=false...
2024-06-04T07:40:09.8251370Z 16.25 [events-ac2] INFO src/securejoin.rs:293: Received secure-join message "vg-auth-required".
2024-06-04T07:40:09.8252240Z 16.25 [events-ac2] INFO src/securejoin/bobstate.rs:269: Bob Step 4 - handling {vc,vg}-auth-required message.
2024-06-04T07:40:09.8253050Z 16.25 [events-ac2] INFO src/securejoin/bobstate.rs:294: Fingerprint verified.
2024-06-04T07:40:09.8253840Z 16.25 [events-ac2] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8254650Z 16.25 [events-ac2] INFO src/e2ee.rs:66: Peerstate for "ci-ttjgct@***" is mutual.
2024-06-04T07:40:09.8255420Z 16.25 [events-ac2] INFO src/mimefactory.rs:1115: Sending secure-join message "vg-request-with-auth".
2024-06-04T07:40:09.8256220Z 16.26 [events-ac2] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#12 to 1717486496.
2024-06-04T07:40:09.8256910Z 16.26 [events-ac2] INFO src/scheduler.rs:819: smtp fake idle - interrupted
2024-06-04T07:40:09.8257510Z 16.26 [events-ac2] INFO src/smtp.rs:696: Selected rows from SMTP queue: [2].
2024-06-04T07:40:09.8258080Z 16.26 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8259270Z 16.26 [events-ac2] INFO src/smtp.rs:564: Try number 1 to send message Msg#14 (entry 2) over SMTP
2024-06-04T07:40:09.8259910Z 16.26 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8260410Z 16.26 [events-ac2] DC_EVENT_MSGS_CHANGED data1=13 data2=15
2024-06-04T07:40:09.8261000Z 16.26 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8261490Z 16.26 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8261990Z 16.26 [events-ac2] DC_EVENT_CHAT_MODIFIED data1=12 data2=0
2024-06-04T07:40:09.8262500Z 16.26 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8263150Z 16.26 [events-ac2] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#12 to 0.
2024-06-04T07:40:09.8263750Z 16.26 [events-ac2] DC_EVENT_MSGS_CHANGED data1=12 data2=16
2024-06-04T07:40:09.8264220Z 16.26 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8264720Z 16.26 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8265200Z 16.26 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8265730Z 16.26 [events-ac2] DC_EVENT_SECUREJOIN_JOINER_PROGRESS data1=10 data2=400
2024-06-04T07:40:09.8266270Z 16.26 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8267010Z 16.26 [events-ac2] INFO src/contact.rs:1841: Recently seen loop waiting for 0h 10m 0s or interrupt
2024-06-04T07:40:09.8267680Z 16.26 [events-ac2] INFO src/imap.rs:1422: Successfully received 1 UIDs.
2024-06-04T07:40:09.8268260Z 16.26 [events-ac2] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8268780Z 16.26 [events-ac2] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
2024-06-04T07:40:09.8269420Z 16.40 [events-ac2] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 12 marked as deleted
2024-06-04T07:40:09.8270180Z 16.40 [events-ac2] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8270850Z 16.53 [events-ac2] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8271810Z 16.69 [events-ac2] INFO src/smtp/send.rs:57: Message len=5505 was SMTP-sent to ci-ttjgct@***,ci-98hw34@***.
2024-06-04T07:40:09.8272880Z 16.69 [events-ac2] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=5505 was SMTP-sent to ci-ttjgct@***,ci-98hw34@***
2024-06-04T07:40:09.8273590Z 16.69 [events-ac2] DC_EVENT_MSG_DELIVERED data1=12 data2=14
2024-06-04T07:40:09.8274110Z 16.69 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8274810Z 16.69 [events-ac2] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8275370Z 16.69 [events-ac2] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8275930Z 16.69 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8276590Z 16.69 [events-ac2] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8277220Z 16.80 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8277740Z 16.80 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8278370Z 16.80 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8279130Z 16.80 [events-ac2] INFO src/imap.rs:1691: Need to refetch "INBOX", got unsolicited EXISTS Exists(1)
2024-06-04T07:40:09.8280070Z 16.84 [events-ac1] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
2024-06-04T07:40:09.8280870Z 16.93 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8281390Z 17.07 [events-ac2] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8281910Z 17.10 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8282390Z 17.20 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8282870Z 17.20 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8283440Z 17.20 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8284210Z 17.20 [events-ac2] INFO src/imap/idle.rs:39: skip idle, got interrupt
2024-06-04T07:40:09.8284770Z 17.23 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8285580Z 17.23 [events-ac1] INFO src/imap.rs:1267: Starting a full FETCH of message set "15".
2024-06-04T07:40:09.8286670Z 17.33 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8287250Z 17.37 [events-ac1] INFO src/imap.rs:1380: Passing message UID 15 to receive_imf().
2024-06-04T07:40:09.8288070Z 17.38 [events-ac1] INFO src/receive_imf.rs:223: Receiving message "Mr.LdU3qpWC1j8.sowx_DwAckA@localhost", seen=false...
2024-06-04T07:40:09.8288920Z 17.38 [events-ac1] INFO src/securejoin.rs:293: Received secure-join message "vg-request-with-auth".
2024-06-04T07:40:09.8289570Z 17.38 [events-ac1] INFO src/securejoin.rs:404: Fingerprint verified.
2024-06-04T07:40:09.8290050Z 17.38 [events-ac1] INFO src/securejoin.rs:451: Auth verified.
2024-06-04T07:40:09.8290530Z 17.38 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8291430Z 17.38 [events-ac1] DC_EVENT_SECUREJOIN_INVITER_PROGRESS data1=10 data2=600
2024-06-04T07:40:09.8292080Z 17.38 [events-ac1] DC_EVENT_CHAT_MODIFIED data1=13 data2=0
2024-06-04T07:40:09.8292580Z 17.38 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8293180Z 17.38 [events-ac1] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#13 to 0.
2024-06-04T07:40:09.8293750Z 17.38 [events-ac1] DC_EVENT_MSGS_CHANGED data1=13 data2=16
2024-06-04T07:40:09.8294180Z 17.38 [events-ac1] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8294650Z 17.38 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8295120Z 17.38 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8295570Z 17.38 [events-ac1] DC_EVENT_CHAT_MODIFIED data1=12 data2=0
2024-06-04T07:40:09.8296010Z 17.38 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8296580Z 17.38 [events-ac1] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#12 to 0.
2024-06-04T07:40:09.8297320Z 17.38 [events-ac1] INFO src/ephemeral.rs:582: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2024-06-04T07:40:09.8298130Z 17.39 [events-ac1] INFO src/e2ee.rs:66: Peerstate for "ci-98hw34@***" is mutual.
2024-06-04T07:40:09.8298790Z 17.39 [events-ac1] INFO src/mimefactory.rs:1042: Sending secure-join message "vg-member-added".
2024-06-04T07:40:09.8299830Z 17.39 [events-ac1] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#12 to 1717486497.
2024-06-04T07:40:09.8300420Z 17.39 [events-ac1] DC_EVENT_MSGS_CHANGED data1=12 data2=17
2024-06-04T07:40:09.8300990Z 17.39 [events-ac1] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8301480Z 17.39 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8301950Z 17.39 [events-ac1] DC_EVENT_CHAT_MODIFIED data1=12 data2=0
2024-06-04T07:40:09.8302440Z 17.39 [events-ac1] DC_EVENT_SECUREJOIN_INVITER_PROGRESS data1=10 data2=800
2024-06-04T07:40:09.8303080Z 17.39 [events-ac1] DC_EVENT_SECUREJOIN_INVITER_PROGRESS data1=10 data2=1000
2024-06-04T07:40:09.8303650Z 17.39 [events-ac1] INFO src/scheduler.rs:819: smtp fake idle - interrupted
2024-06-04T07:40:09.8304190Z 17.39 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8304840Z 17.39 [events-ac1] INFO src/contact.rs:1841: Recently seen loop waiting for 0h 9m 57s or interrupt
2024-06-04T07:40:09.8305710Z 17.39 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8306530Z 17.39 [events-ac1] INFO src/smtp.rs:696: Selected rows from SMTP queue: [2].
2024-06-04T07:40:09.8308420Z 17.39 [events-ac1] INFO src/smtp.rs:564: Try number 1 to send message Msg#17 (entry 2) over SMTP** SECUREJOINT-INVITER PROGRESS 1000 <Account path=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db>
2024-06-04T07:40:09.8310740Z 
2024-06-04T07:40:09.8310990Z 17.39 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8311490Z 17.39 [events-ac1] INFO src/imap.rs:1422: Successfully received 1 UIDs.
2024-06-04T07:40:09.8312000Z 17.39 [events-ac1] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8312460Z 17.39 [events-ac1] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
2024-06-04T07:40:09.8312930Z 17.46 [events-ac2] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8313410Z 17.52 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8313870Z 17.52 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8314400Z 17.52 [events-ac1] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8315060Z 17.59 [events-ac2] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 13 marked as deleted
2024-06-04T07:40:09.8315710Z 17.59 [events-ac2] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8316340Z 17.65 [events-ac1] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8316940Z 17.72 [events-ac2] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8317670Z 17.80 [events-ac1] INFO src/smtp/send.rs:57: Message len=4808 was SMTP-sent to ci-98hw34@***.
2024-06-04T07:40:09.8318610Z 17.80 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=4808 was SMTP-sent to ci-98hw34@***
2024-06-04T07:40:09.8319350Z 17.80 [events-ac1] DC_EVENT_MSG_DELIVERED data1=12 data2=17
2024-06-04T07:40:09.8319810Z 17.80 [events-ac1] DC_EVENT_CHATLIST_ITEM_CHANGED data1=12 data2=0
2024-06-04T07:40:09.8320250Z 17.81 [events-ac1] INFO src/smtp.rs:801: Sending MDNs
2024-06-04T07:40:09.8320810Z 17.81 [events-ac1] INFO src/scheduler.rs:787: smtp fake idle - started
2024-06-04T07:40:09.8321510Z 17.81 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8322160Z 17.81 [events-ac1] INFO src/scheduler.rs:815: smtp has no messages to retry, waiting for interrupt
2024-06-04T07:40:09.8322760Z 17.99 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8323240Z 17.99 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8323790Z 17.99 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8324420Z 18.12 [events-ac2] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8325290Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2024-06-04T07:40:09.8325750Z ~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of events (6347730944) ~~~~~~~~~~~~~~~~~~~~~~~~~
2024-06-04T07:40:09.8335840Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-06-04T07:40:09.8337760Z     self._bootstrap_inner()
2024-06-04T07:40:09.8338390Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-06-04T07:40:09.8339140Z     self.run()
2024-06-04T07:40:09.8340090Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/deltachat/events.py", line 266, in run
2024-06-04T07:40:09.8340910Z     event = lib.dc_get_next_event(event_emitter)
2024-06-04T07:40:09.8341300Z ~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of events (6330904576) ~~~~~~~~~~~~~~~~~~~~~~~~~
2024-06-04T07:40:09.8342050Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-06-04T07:40:09.8342640Z     self._bootstrap_inner()
2024-06-04T07:40:09.8343280Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-06-04T07:40:09.8343890Z     self.run()
2024-06-04T07:40:09.8344720Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/deltachat/events.py", line 266, in run
2024-06-04T07:40:09.8345910Z     event = lib.dc_get_next_event(event_emitter)
2024-06-04T07:40:09.8346310Z ~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of events (6228602880) ~~~~~~~~~~~~~~~~~~~~~~~~~
2024-06-04T07:40:09.8347050Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-06-04T07:40:09.8347690Z     self._bootstrap_inner()
2024-06-04T07:40:09.8348310Z   File "/Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-06-04T07:40:09.8348840Z     self.run()
2024-06-04T07:40:09.8349630Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/deltachat/events.py", line 266, in run
2024-06-04T07:40:09.8350380Z     event = lib.dc_get_next_event(event_emitter)
2024-06-04T07:40:09.8350830Z ~~~~~~~~~~~~~~~~~~~~~~~ Stack of <unknown> (6178025472) ~~~~~~~~~~~~~~~~~~~~~~~~
2024-06-04T07:40:09.8352820Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/execnet/gateway_base.py", line 411, in _perform_spawn
2024-06-04T07:40:09.8353660Z     reply.run()
2024-06-04T07:40:09.8354580Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/execnet/gateway_base.py", line 341, in run
2024-06-04T07:40:09.8355410Z     self._result = func(*args, **kwargs)
2024-06-04T07:40:09.8356370Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/execnet/gateway_base.py", line 1160, in _thread_receiver
2024-06-04T07:40:09.8357150Z     msg = Message.from_io(io)
2024-06-04T07:40:09.8358120Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/execnet/gateway_base.py", line 567, in from_io
2024-06-04T07:40:09.8358950Z     header = io.read(9)  # type 1, channel 4, payload 4
2024-06-04T07:40:09.8359920Z   File "/Users/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.12/site-packages/execnet/gateway_base.py", line 534, in read
2024-06-04T07:40:09.8360770Z     data = self._read(numbytes - len(buf))
2024-06-04T07:40:09.8361200Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2024-06-04T07:40:09.8361760Z --------------------------- Captured stdout teardown ---------------------------
2024-06-04T07:40:09.8363110Z 300.90 [events-ac1] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: Fetch(1, [ModSeq(49), Flags(["\\Seen", "\\Recent"])]) }
2024-06-04T07:40:09.8364050Z 301.16 [events-ac1] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8364730Z 301.16 [events-ac1] INFO src/imap/scan_folders.rs:31: Starting full folder scan
2024-06-04T07:40:09.8365410Z 301.42 [events-ac1] INFO src/imap.rs:552: No new emails in folder "DeltaChat".
2024-06-04T07:40:09.8366080Z 301.55 [events-ac1] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8366680Z 301.68 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8367200Z 301.68 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8367760Z 301.68 [events-ac1] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8368430Z 301.81 [events-ac1] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
2024-06-04T07:40:09.8369390Z 301.97 [events-ac2] INFO src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: Fetch(1, [ModSeq(47), Flags(["\\Seen", "\\Recent"])]) }
2024-06-04T07:40:09.8370260Z 302.24 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8370930Z 302.24 [events-ac2] INFO src/imap.rs:1267: Starting a full FETCH of message set "14".
2024-06-04T07:40:09.8371630Z 302.38 [events-ac2] INFO src/imap.rs:1380: Passing message UID 14 to receive_imf().
2024-06-04T07:40:09.8372480Z 302.39 [events-ac2] INFO src/receive_imf.rs:223: Receiving message "Mr.8btxFzEU-Sl.czqeChkPWqH@localhost", seen=true...
2024-06-04T07:40:09.8373660Z 302.39 [events-ac2] INFO src/securejoin.rs:293: Received secure-join message "vg-member-added".
2024-06-04T07:40:09.8374320Z 302.39 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8374860Z 302.39 [events-ac2] DC_EVENT_SECUREJOIN_JOINER_PROGRESS data1=10 data2=1000
2024-06-04T07:40:09.8375340Z 302.40 [events-ac2] DC_EVENT_CHAT_MODIFIED data1=13 data2=0
2024-06-04T07:40:09.8375800Z 302.40 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8376400Z 302.40 [events-ac2] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#13 to 0.
2024-06-04T07:40:09.8377060Z 302.40 [events-ac2] DC_EVENT_MSGS_CHANGED data1=13 data2=18
2024-06-04T07:40:09.8384380Z 302.40 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8385020Z 302.40 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8385530Z 302.40 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8386360Z 302.40 [events-ac2] INFO src/receive_imf.rs:2204: Recreating chat Chat#13 member list with {ContactId(10), ContactId(1)}.
2024-06-04T07:40:09.8387290Z 302.40 [events-ac2] DC_EVENT_CHAT_MODIFIED data1=13 data2=0
2024-06-04T07:40:09.8387930Z 302.40 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8388790Z 302.40 [events-ac2] INFO src/receive_imf.rs:1674: Message has 1 parts and is assigned to chat #Chat#13.
2024-06-04T07:40:09.8389480Z 302.40 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8390360Z 302.40 [events-ac2] INFO src/receive_imf.rs:450: Received message contains Autocrypt-Gossip for all members of Chat#13, updating timestamp.
2024-06-04T07:40:09.8391430Z 302.40 [events-ac2] INFO src/chat.rs:1337: Set gossiped_timestamp for chat Chat#13 to 1717486496.
2024-06-04T07:40:09.8392280Z 302.40 [events-ac2] INFO src/contact.rs:1841: Recently seen loop waiting for 0h 5m 13s or interrupt
2024-06-04T07:40:09.8392960Z 302.40 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2024-06-04T07:40:09.8393440Z 302.40 [events-ac2] DC_EVENT_MSGS_CHANGED data1=13 data2=19
2024-06-04T07:40:09.8393950Z 302.40 [events-ac2] DC_EVENT_CHATLIST_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8394460Z 302.40 [events-ac2] DC_EVENT_CHATLIST_ITEM_CHANGED data1=13 data2=0
2024-06-04T07:40:09.8395120Z 302.40 [events-ac2] INFO src/imap.rs:1422: Successfully received 1 UIDs.
2024-06-04T07:40:09.8395680Z 302.40 [events-ac2] INFO src/imap.rs:747: 1 mails read from "INBOX".
2024-06-04T07:40:09.8396420Z 302.40 [events-ac2] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
2024-06-04T07:40:09.8397110Z 302.53 [events-ac2] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 14 marked as deleted
2024-06-04T07:40:09.8397950Z 302.53 [events-ac2] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8398630Z 302.66 [events-ac2] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8399300Z 302.66 [events-ac2] INFO src/imap/scan_folders.rs:31: Starting full folder scan
2024-06-04T07:40:09.8399940Z 302.92 [events-ac2] INFO src/imap.rs:552: No new emails in folder "DeltaChat".
2024-06-04T07:40:09.8400340Z ===============  ===============
2024-06-04T07:40:09.8400600Z ARCH=64 AUTHSERV_ID_CANDIDATES= BCC_SELF=0 
2024-06-04T07:40:09.8401420Z BLOBDIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db-blobs 
2024-06-04T07:40:09.8402280Z BOT=0 CONFIGURED_INBOX_FOLDER=INBOX CONFIGURED_MVBOX_FOLDER=DeltaChat 
2024-06-04T07:40:09.8402830Z CONFIGURED_SENTBOX_FOLDER=<unset> CONFIGURED_TRASH_FOLDER=<unset> 
2024-06-04T07:40:09.8403790Z DATABASE_DIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac1/dc.db 
2024-06-04T07:40:09.8404620Z DATABASE_ENCRYPTED=false DATABASE_VERSION=114 DEBUG_LOGGING=0 
2024-06-04T07:40:09.8405140Z DELETE_DEVICE_AFTER=0 DELETE_SERVER_AFTER=0 DELETE_TO_TRASH=<unset> 
2024-06-04T07:40:09.8405840Z DELTACHAT_CORE_VERSION=v1.139.6 DISABLE_IDLE=false DISPLAYNAME=0 
2024-06-04T07:40:09.8406240Z DOWNLOAD_LIMIT=0 E2EE_ENABLED=1 
2024-06-04T07:40:09.8407180Z ENTERED_ACCOUNT_SETTINGS=ci-ttjgct@*** imap:unset:***:unset:0:Automatic:cert_strict:AUTH_NORMAL smtp:unset:0:unset:0:Automatic:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8407960Z FETCH_EXISTING_MSGS=0 FETCHED_EXISTING_MSGS=true 
2024-06-04T07:40:09.8408430Z FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=4 
2024-06-04T07:40:09.8408990Z GOSSIP_PERIOD=172800 IMAP_SERVER_ADMIN="mailto:root@***" 
2024-06-04T07:40:09.8409510Z IMAP_SERVER_COMMENT="Chatmail server" IS_CHATMAIL=true IS_CONFIGURED=1 
2024-06-04T07:40:09.8410070Z JOURNAL_MODE=wal KEY_GEN_TYPE=0 LAST_CANT_DECRYPT_OUTGOING_MSGS=0 
2024-06-04T07:40:09.8410640Z LAST_HOUSEKEEPING=1717486407 LAST_MSG_ID=0 LEVEL=awesome MDNS_ENABLED=1 
2024-06-04T07:40:09.8411190Z MEDIA_QUALITY=0 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 NUM_CPUS=3 
2024-06-04T07:40:09.8411720Z NUMBER_OF_CHAT_MESSAGES=5 NUMBER_OF_CHATS=3 NUMBER_OF_CONTACTS=1 
2024-06-04T07:40:09.8412280Z ONLY_FETCH_MVBOX=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=2 QUOTA_EXCEEDING=0 
2024-06-04T07:40:09.8412890Z SAVE_MIME_HEADERS=false SCAN_ALL_FOLDERS_DEBOUNCE_SECS=60 SECONDARY_ADDRS= 
2024-06-04T07:40:09.8413470Z SELFAVATAR=<unset> SENTBOX_WATCH=0 SHOW_EMAILS=2 SIGN_UNENCRYPTED=0 
2024-06-04T07:40:09.8414030Z SOCKS5_ENABLED=0 SQLITE_VERSION=3.39.4 SYNC_MSGS=0 UPTIME=0h 5m 0s 
2024-06-04T07:40:09.8415420Z USED_ACCOUNT_SETTINGS=ci-ttjgct@*** imap:ci-ttjgct@***:***:***:993:Ssl:cert_strict:AUTH_NORMAL smtp:ci-ttjgct@***:***:***:465:Ssl:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8416220Z VERIFIED_ONE_ON_ONE_CHATS=false WEBRTC_INSTANCE=<unset> 
2024-06-04T07:40:09.8416750Z --------- INBOX 1 messages ---------
2024-06-04T07:40:09.8417090Z Message 15 has empty body
2024-06-04T07:40:09.8417400Z --------- EMPTY FOLDERS: ['DeltaChat']
2024-06-04T07:40:09.8417630Z 
2024-06-04T07:40:09.8417730Z ===============  ===============
2024-06-04T07:40:09.8418060Z ARCH=64 AUTHSERV_ID_CANDIDATES= BCC_SELF=1 
2024-06-04T07:40:09.8419000Z BLOBDIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db-blobs 
2024-06-04T07:40:09.8419890Z BOT=0 CONFIGURED_INBOX_FOLDER=INBOX CONFIGURED_MVBOX_FOLDER=DeltaChat 
2024-06-04T07:40:09.8420460Z CONFIGURED_SENTBOX_FOLDER=<unset> CONFIGURED_TRASH_FOLDER=<unset> 
2024-06-04T07:40:09.8421640Z DATABASE_DIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac2/dc.db 
2024-06-04T07:40:09.8422520Z DATABASE_ENCRYPTED=false DATABASE_VERSION=114 DEBUG_LOGGING=0 
2024-06-04T07:40:09.8423060Z DELETE_DEVICE_AFTER=0 DELETE_SERVER_AFTER=1 DELETE_TO_TRASH=<unset> 
2024-06-04T07:40:09.8423610Z DELTACHAT_CORE_VERSION=v1.139.6 DISABLE_IDLE=false DISPLAYNAME=0 
2024-06-04T07:40:09.8424060Z DOWNLOAD_LIMIT=0 E2EE_ENABLED=1 
2024-06-04T07:40:09.8425000Z ENTERED_ACCOUNT_SETTINGS=ci-98hw34@*** imap:unset:***:unset:0:Automatic:cert_strict:AUTH_NORMAL smtp:unset:0:unset:0:Automatic:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8425790Z FETCH_EXISTING_MSGS=0 FETCHED_EXISTING_MSGS=true 
2024-06-04T07:40:09.8426330Z FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=4 
2024-06-04T07:40:09.8426960Z GOSSIP_PERIOD=0 IMAP_SERVER_ADMIN="mailto:root@***" 
2024-06-04T07:40:09.8427610Z IMAP_SERVER_COMMENT="Chatmail server" IS_CHATMAIL=true IS_CONFIGURED=1 
2024-06-04T07:40:09.8428210Z JOURNAL_MODE=wal KEY_GEN_TYPE=0 LAST_CANT_DECRYPT_OUTGOING_MSGS=0 
2024-06-04T07:40:09.8428780Z LAST_HOUSEKEEPING=1717486411 LAST_MSG_ID=0 LEVEL=awesome MDNS_ENABLED=1 
2024-06-04T07:40:09.8429380Z MEDIA_QUALITY=0 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 NUM_CPUS=3 
2024-06-04T07:40:09.8429940Z NUMBER_OF_CHAT_MESSAGES=4 NUMBER_OF_CHATS=3 NUMBER_OF_CONTACTS=1 
2024-06-04T07:40:09.8430520Z ONLY_FETCH_MVBOX=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=2 QUOTA_EXCEEDING=0 
2024-06-04T07:40:09.8431340Z SAVE_MIME_HEADERS=false SCAN_ALL_FOLDERS_DEBOUNCE_SECS=60 SECONDARY_ADDRS= 
2024-06-04T07:40:09.8431940Z SELFAVATAR=<unset> SENTBOX_WATCH=0 SHOW_EMAILS=2 SIGN_UNENCRYPTED=0 
2024-06-04T07:40:09.8432500Z SOCKS5_ENABLED=0 SQLITE_VERSION=3.39.4 SYNC_MSGS=0 UPTIME=0h 5m 1s 
2024-06-04T07:40:09.8433800Z USED_ACCOUNT_SETTINGS=ci-98hw34@*** imap:ci-98hw34@***:***:***:993:Ssl:cert_strict:AUTH_NORMAL smtp:ci-98hw34@***:***:***:465:Ssl:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8434590Z VERIFIED_ONE_ON_ONE_CHATS=false WEBRTC_INSTANCE=<unset> 
2024-06-04T07:40:09.8435040Z --------- INBOX 1 messages ---------
2024-06-04T07:40:09.8435350Z Message 14 has empty body
2024-06-04T07:40:09.8435690Z --------- EMPTY FOLDERS: ['DeltaChat']
2024-06-04T07:40:09.8435940Z 
2024-06-04T07:40:09.8436010Z ===============  ===============
2024-06-04T07:40:09.8436340Z ARCH=64 AUTHSERV_ID_CANDIDATES= BCC_SELF=0 
2024-06-04T07:40:09.8437250Z BLOBDIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac3/dc.db-blobs 
2024-06-04T07:40:09.8438180Z BOT=0 CONFIGURED_INBOX_FOLDER=INBOX CONFIGURED_MVBOX_FOLDER=DeltaChat 
2024-06-04T07:40:09.8438740Z CONFIGURED_SENTBOX_FOLDER=<unset> CONFIGURED_TRASH_FOLDER=<unset> 
2024-06-04T07:40:09.8439760Z DATABASE_DIR=/private/var/folders/lr/439_fwvd3m76p9vy50d57kcc0000gn/T/pytest-of-runner/pytest-0/popen-gw1/test_verified_group_vs_delete_0/ac3/dc.db 
2024-06-04T07:40:09.8440650Z DATABASE_ENCRYPTED=false DATABASE_VERSION=114 DEBUG_LOGGING=0 
2024-06-04T07:40:09.8441180Z DELETE_DEVICE_AFTER=0 DELETE_SERVER_AFTER=0 DELETE_TO_TRASH=<unset> 
2024-06-04T07:40:09.8441720Z DELTACHAT_CORE_VERSION=v1.139.6 DISABLE_IDLE=false DISPLAYNAME=0 
2024-06-04T07:40:09.8442150Z DOWNLOAD_LIMIT=0 E2EE_ENABLED=1 
2024-06-04T07:40:09.8443030Z ENTERED_ACCOUNT_SETTINGS=ci-98hw34@*** imap:unset:***:unset:0:Automatic:cert_strict:AUTH_NORMAL smtp:unset:0:unset:0:Automatic:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8443820Z FETCH_EXISTING_MSGS=0 FETCHED_EXISTING_MSGS=true 
2024-06-04T07:40:09.8444360Z FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=4 
2024-06-04T07:40:09.8444970Z GOSSIP_PERIOD=172800 IMAP_SERVER_ADMIN="mailto:root@***" 
2024-06-04T07:40:09.8445500Z IMAP_SERVER_COMMENT="Chatmail server" IS_CHATMAIL=true IS_CONFIGURED=1 
2024-06-04T07:40:09.8446070Z JOURNAL_MODE=wal KEY_GEN_TYPE=0 LAST_CANT_DECRYPT_OUTGOING_MSGS=0 
2024-06-04T07:40:09.8446660Z LAST_HOUSEKEEPING=1717486490 LAST_MSG_ID=0 LEVEL=awesome MDNS_ENABLED=1 
2024-06-04T07:40:09.8447380Z MEDIA_QUALITY=0 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 NUM_CPUS=3 
2024-06-04T07:40:09.8447970Z NUMBER_OF_CHAT_MESSAGES=2 NUMBER_OF_CHATS=2 NUMBER_OF_CONTACTS=0 
2024-06-04T07:40:09.8448540Z ONLY_FETCH_MVBOX=0 PRIVATE_KEY_COUNT=2 PUBLIC_KEY_COUNT=0 QUOTA_EXCEEDING=0 
2024-06-04T07:40:09.8449140Z SAVE_MIME_HEADERS=false SCAN_ALL_FOLDERS_DEBOUNCE_SECS=60 SECONDARY_ADDRS= 
2024-06-04T07:40:09.8449740Z SELFAVATAR=<unset> SENTBOX_WATCH=0 SHOW_EMAILS=2 SIGN_UNENCRYPTED=0 
2024-06-04T07:40:09.8450290Z SOCKS5_ENABLED=0 SQLITE_VERSION=3.39.4 SYNC_MSGS=0 UPTIME=0h 4m 54s 
2024-06-04T07:40:09.8451520Z USED_ACCOUNT_SETTINGS=ci-98hw34@*** imap:ci-98hw34@***:***:***:993:Ssl:cert_strict:AUTH_NORMAL smtp:ci-98hw34@***:***:***:465:Ssl:cert_strict:AUTH_NORMAL 
2024-06-04T07:40:09.8452270Z VERIFIED_ONE_ON_ONE_CHATS=false WEBRTC_INSTANCE=<unset> 
2024-06-04T07:40:09.8452760Z --------- EMPTY FOLDERS: ['DeltaChat', 'INBOX']
2024-06-04T07:40:09.8453020Z 
2024-06-04T07:40:09.8453030Z 
2024-06-04T07:40:09.8453180Z 303.05 [MAIN-ac3] stop_ongoing
2024-06-04T07:40:09.8453600Z 303.05 [MAIN-ac3] dc_stop_io (stop core IO scheduler)
2024-06-04T07:40:09.8454040Z 303.05 [events-ac3] EVENT THREAD FINISHED
2024-06-04T07:40:09.8454470Z 303.05 [MAIN-ac3] wait for event thread to finish
2024-06-04T07:40:09.8455060Z 303.05 [MAIN-ac3] remove dc_context references, making the Account unusable
2024-06-04T07:40:09.8455740Z 303.06 [events-ac2] INFO src/imap.rs:552: No new emails in folder "INBOX".
2024-06-04T07:40:09.8456400Z 303.07 [MAIN-ac3] shutdown finished
2024-06-04T07:40:09.8456890Z 303.19 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8457420Z 303.19 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8458020Z 303.19 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8458470Z 303.20 [MAIN-ac2] stop_ongoing
2024-06-04T07:40:09.8458790Z 303.20 [MAIN-ac2] dc_stop_io (stop core IO scheduler)
2024-06-04T07:40:09.8459140Z 303.20 [events-ac2] EVENT THREAD FINISHED
2024-06-04T07:40:09.8459490Z 303.20 [MAIN-ac2] wait for event thread to finish
2024-06-04T07:40:09.8459960Z 303.20 [MAIN-ac2] remove dc_context references, making the Account unusable
2024-06-04T07:40:09.8460370Z 303.20 [MAIN-ac2] shutdown finished
2024-06-04T07:40:09.8460640Z 303.33 [MAIN-ac1] stop_ongoing
2024-06-04T07:40:09.8460950Z 303.33 [MAIN-ac1] dc_stop_io (stop core IO scheduler)
2024-06-04T07:40:09.8461300Z 303.33 [events-ac1] EVENT THREAD FINISHED
2024-06-04T07:40:09.8461640Z 303.33 [MAIN-ac1] wait for event thread to finish
2024-06-04T07:40:09.8462090Z 303.33 [MAIN-ac1] remove dc_context references, making the Account unusable
2024-06-04T07:40:09.8462500Z 303.34 [MAIN-ac1] shutdown finished
2024-06-04T07:40:09.8462840Z ================== 1 failed, 174 passed in 407.91s (0:06:47) ===================
2024-06-04T07:40:09.8463810Z py: exit 1 (408.19 seconds) /Users/runner/work/deltachat-core-rust/deltachat-core-rust/python> pytest -n6 --extra-info -v -rsXx --ignored --strict-tls tests examples pid=4824
2024-06-04T07:40:09.8464590Z   mypy: OK (19.87=setup[18.63]+cmd[1.24] seconds)
2024-06-04T07:40:09.8464910Z   doc: OK (14.71=setup[13.15]+cmd[1.56] seconds)
2024-06-04T07:40:09.8465250Z   py: FAIL code 1 (420.11=setup[11.92]+cmd[408.19] seconds)
2024-06-04T07:40:09.8465580Z   evaluation failed :( (454.74 seconds)
2024-06-04T07:40:09.8679750Z ##[error]Process completed with exit code 255.

link2xt · 2024-06-04T09:32:43Z

ac2 expunges messages from INBOX, then goes IDLE but does not notice "member added" message which should be there:

2024-06-04T07:40:09.8312930Z 17.46 [events-ac2] INFO src/imap.rs:747: 0 mails read from "INBOX".
2024-06-04T07:40:09.8315060Z 17.59 [events-ac2] DC_EVENT_IMAP_MESSAGE_DELETED data1=0 data2=IMAP messages 13 marked as deleted
2024-06-04T07:40:09.8315710Z 17.59 [events-ac2] INFO src/imap/select_folder.rs:41: Expunge messages in "INBOX".
2024-06-04T07:40:09.8316940Z 17.72 [events-ac2] INFO src/imap/select_folder.rs:44: close/expunge succeeded
2024-06-04T07:40:09.8322760Z 17.99 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2024-06-04T07:40:09.8323240Z 17.99 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2024-06-04T07:40:09.8323790Z 17.99 [events-ac2] INFO src/scheduler.rs:674: IMAP session supports IDLE, using it.
2024-06-04T07:40:09.8324420Z 18.12 [events-ac2] INFO src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state

link2xt · 2024-06-04T12:11:35Z

The problem is likely that message arrives while the folder is closed and we don't notice that message arrived when we SELECT the folder back.

Here we call fetch_move_delete:

deltachat-core-rust/src/scheduler.rs

Line 590 in 48b4cfc

.fetch_move_delete(ctx, &mut session, &watch_folder, folder_meaning)

It removes previous message and closes folder to expunge it:

deltachat-core-rust/src/imap.rs

Lines 1061 to 1065 in 48b4cfc

    
           // Expunge folder if needed, e.g. if some jobs have 
        
           // deleted messages on the server. 
        
           if let Err(err) = self.maybe_close_folder(context).await { 
        
               warn!(context, "failed to close folder: {:?}", err); 
        
           }

After we close the inbox, message may arrive into it.

Then we likely skip scanning folders and call sync_seen_flags.
sync_seen_flags calls select_folder and reselects the INBOX:

deltachat-core-rust/src/imap.rs

Lines 1134 to 1136 in 48b4cfc

    
           self.select_folder(context, Some(folder)) 
        
               .await 
        
               .context("failed to select folder")?;

Once sync_seen_flags exits, we emit DC_EVENT_IMAP_INBOX_IDLE and call IDLE.

There is no unsolicited EXISTS because message arrived when the folder was closed and when folder is selected by sync_seen_flags it likely gets a single EXISTS which is not considered unsolicited, it is a part of SELECT response. So we go IDLE even though there is a message in the INBOX.

I have not decided how to fix it yet because we call select_folder in many places. We can try to notice that UIDNEXT has advanced while the folder is closed or just add a flag that remembers that. Should probably always use select_with_uidvalidity instead of select_folder and not ignore the result. It takes care to check if new mails have arrived by looking at UIDNEXT and falling back to STATUS command. If select_with_uidvalidity returns true, we should try to fetch at least once before going IDLE. Essentially the problem is closing the folder and then calling plain select_folder.

iequidoo self-assigned this Jan 23, 2024

iequidoo added a commit that referenced this issue Jan 23, 2024

test: try to reproduce (#5201)

b0a3e38

link2xt mentioned this issue Jan 30, 2024

add Background Fetch method #5104

Merged

2 tasks

iequidoo mentioned this issue Feb 2, 2024

Context::set_config(): Restart IO scheduler if needed (#5111) #5117

Merged

iequidoo added a commit that referenced this issue Feb 5, 2024

test: try to reproduce (#5201)

16e31e0

iequidoo added a commit that referenced this issue Feb 6, 2024

test: try to reproduce (#5201)

f4c1ce6

iequidoo added a commit that referenced this issue Feb 7, 2024

test: try to reproduce (#5201)

384bb92

iequidoo added a commit that referenced this issue Feb 7, 2024

test: try to reproduce (#5201)

e7d88fa

iequidoo added a commit that referenced this issue Feb 7, 2024

fix: Guarantee immediate message deletion if delete_server_after == 0 (…

483e532

…#5201)

iequidoo mentioned this issue Feb 7, 2024

fix: Guarantee immediate message deletion if delete_server_after == 0 (#5201) #5252

Merged

iequidoo added a commit that referenced this issue Feb 7, 2024

fix: Guarantee immediate message deletion if delete_server_after == 0 (…

fba27ff

…#5201)

iequidoo added a commit that referenced this issue Feb 8, 2024

test: delete_server_after="1" should cause immediate message deletion (…

630d4e7

…#5201)

iequidoo added a commit that referenced this issue Feb 8, 2024

test: delete_server_after="1" should cause immediate message deletion (…

ecd4d2a

…#5201)

iequidoo mentioned this issue Feb 16, 2024

fix: Create new Peerstate for unencrypted message with already known Autocrypt key, but a new address #5269

Merged

iequidoo mentioned this issue Mar 19, 2024

fix: Update MemberListTimestamp when sending a group message #5345

Merged

iequidoo removed their assignment Apr 24, 2024

link2xt mentioned this issue Jun 4, 2024

fix: retry sending MDNs on temporary error #5665

Merged

link2xt added the bug Something is not working label Jun 4, 2024

link2xt self-assigned this Jun 4, 2024

This was referenced Jun 4, 2024

refactor(imap): make select_folder() accept non-optional folder #5668

Merged

fix: do not miss new messages while expunging the folder #5669

Merged

link2xt closed this as completed in #5669 Jun 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Test `test_verified_group_vs_delete_server_after` is flaky #5201

Test `test_verified_group_vs_delete_server_after` is flaky #5201

link2xt commented Jan 21, 2024

iequidoo commented Jan 23, 2024

link2xt commented Jan 23, 2024

iequidoo commented Jan 24, 2024

iequidoo commented Jan 29, 2024

link2xt commented Jun 4, 2024

link2xt commented Jun 4, 2024

link2xt commented Jun 4, 2024 •

edited

Loading

Test test_verified_group_vs_delete_server_after is flaky #5201

Test test_verified_group_vs_delete_server_after is flaky #5201

Comments

link2xt commented Jan 21, 2024

iequidoo commented Jan 23, 2024

link2xt commented Jan 23, 2024

iequidoo commented Jan 24, 2024

iequidoo commented Jan 29, 2024

link2xt commented Jun 4, 2024

link2xt commented Jun 4, 2024

link2xt commented Jun 4, 2024 • edited Loading

Test `test_verified_group_vs_delete_server_after` is flaky #5201

Test `test_verified_group_vs_delete_server_after` is flaky #5201

link2xt commented Jun 4, 2024 •

edited

Loading