test_move_works is flaky because of resync #4547
Description
Since #4544 is merged the test has become flaky.
An example of a failure is at https://github.com/deltachat/deltachat-core-rust/actions/runs/5567072431/jobs/10178735126
Copy-paste of the log for archive:
2023-07-17T06:43:12.2363743Z plugins: deltachat-0.1.dev1+gd762753, timeout-2.1.0, xdist-3.3.1
...
2023-07-17T06:50:25.1407235Z tests/test_1_online.py::TestOnlineConfigureFails::test_invalid_password
2023-07-17T06:50:25.3082716Z [gw1] [100%] PASSED tests/test_1_online.py::TestOnlineConfigureFails::test_invalid_password
2023-07-17T06:50:25.3083292Z
2023-07-17T06:50:25.3083981Z =================================== FAILURES ===================================
2023-07-17T06:50:25.3084326Z _______________________________ test_move_works ________________________________
2023-07-17T06:50:25.3085027Z [gw3] linux -- Python 3.7.17 /home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/bin/python
2023-07-17T06:50:25.3085302Z
2023-07-17T06:50:25.3085492Z acfactory = <deltachat.testplugin.ACFactory object at 0x7f0abe07c090>
2023-07-17T06:50:25.3085712Z
2023-07-17T06:50:25.3085825Z def test_move_works(acfactory):
2023-07-17T06:50:25.3086114Z ac1 = acfactory.new_online_configuring_account()
2023-07-17T06:50:25.3086452Z ac2 = acfactory.new_online_configuring_account(mvbox_move=True)
2023-07-17T06:50:25.3086763Z acfactory.bring_accounts_online()
2023-07-17T06:50:25.3087049Z chat = acfactory.get_accepted_chat(ac1, ac2)
2023-07-17T06:50:25.3087322Z chat.send_text("message1")
2023-07-17T06:50:25.3087527Z
2023-07-17T06:50:25.3087740Z # Message is moved to the movebox
2023-07-17T06:50:25.3088025Z > ac2._evtracker.get_matching("DC_EVENT_IMAP_MESSAGE_MOVED")
2023-07-17T06:50:25.3088214Z
2023-07-17T06:50:25.3088592Z tests/test_1_online.py:349:
2023-07-17T06:50:25.3088858Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2023-07-17T06:50:25.3089274Z .tox/py/lib/python3.7/site-packages/deltachat/events.py:119: in get_matching
2023-07-17T06:50:25.3089637Z for ev in self.iter_events(timeout=timeout, check_error=check_error):
2023-07-17T06:50:25.3090230Z .tox/py/lib/python3.7/site-packages/deltachat/events.py:115: in iter_events
2023-07-17T06:50:25.3090638Z yield self.get(timeout=timeout, check_error=check_error)
2023-07-17T06:50:25.3091055Z .tox/py/lib/python3.7/site-packages/deltachat/events.py:108: in get
2023-07-17T06:50:25.3091429Z ev = self._event_queue.get(timeout=timeout)
2023-07-17T06:50:25.3091770Z /opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/queue.py:170: in get
2023-07-17T06:50:25.3092074Z self.not_empty.wait()
2023-07-17T06:50:25.3092342Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2023-07-17T06:50:25.3092511Z
2023-07-17T06:50:25.3216332Z self = <Condition(<unlocked _thread.lock object at 0x7f0abe6f67e0>, 0)>
2023-07-17T06:50:25.3216638Z timeout = None
2023-07-17T06:50:25.3216768Z
2023-07-17T06:50:25.3216878Z def wait(self, timeout=None):
2023-07-17T06:50:25.3217158Z """Wait until notified or until a timeout occurs.
2023-07-17T06:50:25.3217389Z
2023-07-17T06:50:25.3217649Z If the calling thread has not acquired the lock when this method is
2023-07-17T06:50:25.3217955Z called, a RuntimeError is raised.
2023-07-17T06:50:25.3218177Z
2023-07-17T06:50:25.3218451Z This method releases the underlying lock, and then blocks until it is
2023-07-17T06:50:25.3218806Z awakened by a notify() or notify_all() call for the same condition
2023-07-17T06:50:25.3219165Z variable in another thread, or until the optional timeout occurs. Once
2023-07-17T06:50:25.3219679Z awakened or timed out, it re-acquires the lock and returns.
2023-07-17T06:50:25.3219921Z
2023-07-17T06:50:25.3220184Z When the timeout argument is present and not None, it should be a
2023-07-17T06:50:25.3222265Z floating point number specifying a timeout for the operation in seconds
2023-07-17T06:50:25.3222579Z (or fractions thereof).
2023-07-17T06:50:25.3222773Z
2023-07-17T06:50:25.3223029Z When the underlying lock is an RLock, it is not released using its
2023-07-17T06:50:25.3223375Z release() method, since this may not actually unlock the lock when it
2023-07-17T06:50:25.3223739Z was acquired multiple times recursively. Instead, an internal interface
2023-07-17T06:50:25.3224514Z of the RLock class is used, which really unlocks it even when it has
2023-07-17T06:50:25.3224875Z been recursively acquired several times. Another internal interface is
2023-07-17T06:50:25.3225228Z then used to restore the recursion level when the lock is reacquired.
2023-07-17T06:50:25.3225484Z
2023-07-17T06:50:25.3225658Z """
2023-07-17T06:50:25.3225870Z if not self._is_owned():
2023-07-17T06:50:25.3226254Z raise RuntimeError("cannot wait on un-acquired lock")
2023-07-17T06:50:25.3226535Z waiter = _allocate_lock()
2023-07-17T06:50:25.3226752Z waiter.acquire()
2023-07-17T06:50:25.3226992Z self._waiters.append(waiter)
2023-07-17T06:50:25.3227248Z saved_state = self._release_save()
2023-07-17T06:50:25.3227474Z gotit = False
2023-07-17T06:50:25.3227759Z try: # restore state no matter what (e.g., KeyboardInterrupt)
2023-07-17T06:50:25.3228038Z if timeout is None:
2023-07-17T06:50:25.3228266Z > waiter.acquire()
2023-07-17T06:50:25.3228500Z E Failed: Timeout >150.0s
2023-07-17T06:50:25.3228654Z
2023-07-17T06:50:25.3228834Z /opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/threading.py:296: Failed
2023-07-17T06:50:25.3229304Z ----------------------------- Captured stdout call -----------------------------
2023-07-17T06:50:25.3230008Z [acsetup] 0.023 started configure on <Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac1/dc.db>
2023-07-17T06:50:25.3230599Z [acsetup] 0.045 started configure on <Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac2/dc.db>
2023-07-17T06:50:25.3230942Z bringing accounts online
2023-07-17T06:50:25.3231663Z wait_all_configured finds accounts= {<Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac1/dc.db>: 'CONFIGURING', <Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac2/dc.db>: 'CONFIGURING'}
2023-07-17T06:50:25.3232275Z 5.66 [events-ac1] INFO src/scheduler.rs:64: starting IO
2023-07-17T06:50:25.3232655Z 5.66 [events-ac1] INFO src/scheduler.rs:333: starting inbox loop
2023-07-17T06:50:25.3233013Z 5.66 [events-ac1] INFO src/job.rs:264: Loading job.
2023-07-17T06:50:25.3233386Z 5.66 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3233765Z 5.66 [events-ac1] INFO src/imap.rs:309: Connecting to IMAP server
2023-07-17T06:50:25.3234230Z 5.66 [events-ac1] INFO src/location.rs:678: Location loop is waiting for 24h 0m 0s or interrupt
2023-07-17T06:50:25.3234650Z 5.66 [events-ac1] INFO src/scheduler.rs:649: starting smtp loop
2023-07-17T06:50:25.3235153Z ac1 waiting for inbox IDLE to become ready
2023-07-17T06:50:25.3235535Z 5.67 [events-ac1] INFO src/smtp.rs:655: Selected rows from SMTP queue: [].
2023-07-17T06:50:25.3235914Z 5.67 [events-ac1] INFO src/smtp.rs:758: Sending MDNs
2023-07-17T06:50:25.3236285Z 5.67 [events-ac1] INFO src/scheduler.rs:688: smtp fake idle - started
2023-07-17T06:50:25.3236680Z 5.67 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3237133Z 5.67 [events-ac1] INFO src/scheduler.rs:710: smtp has no messages to retry, waiting for interrupt
2023-07-17T06:50:25.3237650Z 5.67 [events-ac1] INFO src/ephemeral.rs:567: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2023-07-17T06:50:25.3238087Z 5.67 [events-ac1] INFO src/scheduler.rs:812: scheduler is running
2023-07-17T06:50:25.3238549Z 5.67 [events-ac1] INFO src/contact.rs:1648: Recently seen loop waiting for 24h 0m 0s or interrupt
2023-07-17T06:50:25.3239031Z 5.67 [events-ac1] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into 65.109.227.209:993.
2023-07-17T06:50:25.3239642Z 5.67 [events-ac1] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into [2a01:4f9:c010:8f89::1]:993.
2023-07-17T06:50:25.3240084Z 6.13 [events-ac1] INFO src/imap.rs:378: Logging into IMAP server with LOGIN
2023-07-17T06:50:25.3240542Z 6.98 [events-ac1] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as z4nxe@ci.testrun.org
2023-07-17T06:50:25.3241183Z 6.98 [events-ac1] INFO src/imap.rs:394: Successfully logged into IMAP server
2023-07-17T06:50:25.3241641Z 7.41 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder DeltaChat
2023-07-17T06:50:25.3242096Z 7.71 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Trash
2023-07-17T06:50:25.3242555Z 8.02 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Archive
2023-07-17T06:50:25.3242993Z 8.32 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Sent
2023-07-17T06:50:25.3243446Z 8.62 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Drafts
2023-07-17T06:50:25.3243879Z 8.92 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Junk
2023-07-17T06:50:25.3244322Z 9.21 [events-ac1] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder INBOX
2023-07-17T06:50:25.3244728Z 9.21 [events-ac1] INFO src/sql.rs:777: Start housekeeping...
2023-07-17T06:50:25.3245087Z 9.21 [events-ac1] INFO src/sql.rs:823: 3 files in use.
2023-07-17T06:50:25.3245435Z 9.21 [events-ac1] INFO src/sql.rs:758: Housekeeping done.
2023-07-17T06:50:25.3245808Z 9.36 [events-ac1] INFO src/imap.rs:631: Folder "Sent" is empty.
2023-07-17T06:50:25.3246193Z 9.65 [events-ac1] INFO src/imap.rs:631: Folder "DeltaChat" is empty.
2023-07-17T06:50:25.3246716Z 10.09 [events-ac1] INFO src/imap.rs:945: Done fetching existing messages.
2023-07-17T06:50:25.3247128Z 10.23 [events-ac1] INFO src/imap.rs:887: 0 mails read from "INBOX".
2023-07-17T06:50:25.3247544Z 10.23 [events-ac1] INFO src/imap/scan_folders.rs:27: Starting full folder scan
2023-07-17T06:50:25.3247934Z 10.53 [events-ac1] INFO src/imap.rs:631: Folder "Junk" is empty.
2023-07-17T06:50:25.3248317Z 10.53 [events-ac1] INFO src/imap.rs:719: No new emails in folder Junk
2023-07-17T06:50:25.3248702Z 10.68 [events-ac1] INFO src/imap.rs:719: No new emails in folder Sent
2023-07-17T06:50:25.3249086Z 10.83 [events-ac1] INFO src/imap.rs:631: Folder "Archive" is empty.
2023-07-17T06:50:25.3249488Z 10.83 [events-ac1] INFO src/imap.rs:719: No new emails in folder Archive
2023-07-17T06:50:25.3249889Z 10.98 [events-ac1] INFO src/imap.rs:719: No new emails in folder DeltaChat
2023-07-17T06:50:25.3250280Z 11.14 [events-ac1] INFO src/imap.rs:719: No new emails in folder INBOX
2023-07-17T06:50:25.3250675Z 11.29 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3251052Z 11.29 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2023-07-17T06:50:25.3251475Z 11.29 [events-ac1] INFO src/scheduler.rs:577: IMAP session supports IDLE, using it.
2023-07-17T06:50:25.3251982Z 11.29 [events-ac1] INFO src/imap/idle.rs:37: skip idle, got interrupt InterruptInfo { probe_network: false }
2023-07-17T06:50:25.3252406Z 11.29 [events-ac1] INFO src/job.rs:264: Loading job.
2023-07-17T06:50:25.3252700Z 11.29 [MAIN-ac1] inbox IDLE ready
2023-07-17T06:50:25.3253162Z 11.44 [events-ac1] WARNING src/quota.rs:165: cannot get highest quota usage: no quota_resource found, this is unexpected
2023-07-17T06:50:25.3253608Z 11.44 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3253996Z 11.59 [events-ac1] INFO src/imap.rs:887: 0 mails read from "INBOX".
2023-07-17T06:50:25.3254381Z 11.74 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3254770Z 11.74 [events-ac1] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2023-07-17T06:50:25.3255183Z 11.74 [events-ac1] INFO src/scheduler.rs:577: IMAP session supports IDLE, using it.
2023-07-17T06:50:25.3255645Z 11.88 [events-ac1] INFO src/imap/idle.rs:59: INBOX: Idle entering wait-on-remote state
2023-07-17T06:50:25.3256046Z 14.39 [events-ac2] INFO src/scheduler.rs:64: starting IO
2023-07-17T06:50:25.3256417Z 14.39 [events-ac2] INFO src/scheduler.rs:333: starting inbox loop
2023-07-17T06:50:25.3256776Z 14.39 [events-ac2] INFO src/job.rs:264: Loading job.
2023-07-17T06:50:25.3257138Z 14.39 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3257632Z 14.39 [events-ac2] INFO src/imap.rs:309: Connecting to IMAP server
2023-07-17T06:50:25.3258043Z 14.39 [events-ac2] INFO src/scheduler.rs:613: starting simple loop for Mvbox
2023-07-17T06:50:25.3258434Z 14.39 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3258813Z 14.39 [events-ac2] INFO src/imap.rs:309: Connecting to IMAP server
2023-07-17T06:50:25.3259267Z 14.39 [events-ac2] INFO src/location.rs:678: Location loop is waiting for 24h 0m 0s or interrupt
2023-07-17T06:50:25.3259680Z 14.39 [events-ac2] INFO src/scheduler.rs:649: starting smtp loop
2023-07-17T06:50:25.3260071Z 14.39 [events-ac2] INFO src/smtp.rs:655: Selected rows from SMTP queue: [].
2023-07-17T06:50:25.3260438Z 14.39 [events-ac2] INFO src/smtp.rs:758: Sending MDNs
2023-07-17T06:50:25.3260818Z 14.39 [events-ac2] INFO src/scheduler.rs:688: smtp fake idle - started
2023-07-17T06:50:25.3261206Z 14.39 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3261662Z 14.39 [events-ac2] INFO src/scheduler.rs:710: smtp has no messages to retry, waiting for interrupt
2023-07-17T06:50:25.3262152Z 14.39 [events-ac2] INFO src/contact.rs:1648: Recently seen loop waiting for 24h 0m 0s or interrupt
2023-07-17T06:50:25.3262480Z ac2 waiting for inbox IDLE to become ready
2023-07-17T06:50:25.3263003Z 14.39 [events-ac2] INFO src/ephemeral.rs:567: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2023-07-17T06:50:25.3263442Z 14.39 [events-ac2] INFO src/scheduler.rs:812: scheduler is running
2023-07-17T06:50:25.3263889Z 14.39 [events-ac2] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into 65.109.227.209:993.
2023-07-17T06:50:25.3264350Z 14.39 [events-ac2] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into 65.109.227.209:993.
2023-07-17T06:50:25.3264900Z 14.39 [events-ac2] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into [2a01:4f9:c010:8f89::1]:993.
2023-07-17T06:50:25.3265449Z 14.39 [events-ac2] INFO src/net.rs:70: Resolved mail.ci.testrun.org:993 into [2a01:4f9:c010:8f89::1]:993.
2023-07-17T06:50:25.3265883Z 15.00 [events-ac2] INFO src/imap.rs:378: Logging into IMAP server with LOGIN
2023-07-17T06:50:25.3266302Z 15.10 [events-ac2] INFO src/imap.rs:378: Logging into IMAP server with LOGIN
2023-07-17T06:50:25.3266755Z 16.06 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as yamx7@ci.testrun.org
2023-07-17T06:50:25.3267209Z 16.06 [events-ac2] INFO src/imap.rs:394: Successfully logged into IMAP server
2023-07-17T06:50:25.3267618Z 16.21 [events-ac2] INFO src/imap.rs:631: Folder "DeltaChat" is empty.
2023-07-17T06:50:25.3268029Z 16.21 [events-ac2] INFO src/imap.rs:719: No new emails in folder DeltaChat
2023-07-17T06:50:25.3268477Z 16.25 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as yamx7@ci.testrun.org
2023-07-17T06:50:25.3268908Z 16.25 [events-ac2] INFO src/imap.rs:394: Successfully logged into IMAP server
2023-07-17T06:50:25.3269352Z 16.36 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3269744Z 16.36 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2023-07-17T06:50:25.3270164Z 16.36 [events-ac2] INFO src/scheduler.rs:577: IMAP session supports IDLE, using it.
2023-07-17T06:50:25.3270513Z 16.36 [MAIN-ac2] inbox IDLE ready
2023-07-17T06:50:25.3271196Z finished, account2state {<Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac1/dc.db>: 'IDLEREADY', <Account path=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac2/dc.db>: 'IDLEREADY'}
2023-07-17T06:50:25.3271655Z all accounts online
2023-07-17T06:50:25.3272036Z 16.36 [events-ac1] INFO src/contact.rs:737: added contact id=10 addr=yamx7@ci.testrun.org
2023-07-17T06:50:25.3272449Z 16.36 [events-ac1] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2023-07-17T06:50:25.3272811Z 16.36 [events-ac1] DC_EVENT_MSGS_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3273263Z 16.36 [events-ac1] INFO src/e2ee.rs:85: peerstate for "yamx7@ci.testrun.org" missing, cannot encrypt
2023-07-17T06:50:25.3273772Z 16.36 [events-ac1] DC_EVENT_MSGS_CHANGED data1=12 data2=12
2023-07-17T06:50:25.3274233Z 16.36 [events-ac1] INFO src/ephemeral.rs:567: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt
2023-07-17T06:50:25.3274686Z 16.36 [events-ac1] INFO src/scheduler.rs:714: smtp fake idle - interrupted
2023-07-17T06:50:25.3276371Z 16.36 [events-ac2] INFO src/contact.rs:737: added contact id=10 addr=z4nxe@ci.testrun.org
2023-07-17T06:50:25.3276786Z 16.36 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2023-07-17T06:50:25.3277150Z 16.36 [events-ac2] DC_EVENT_MSGS_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3277558Z 16.36 [events-ac1] INFO src/smtp.rs:655: Selected rows from SMTP queue: [1].
2023-07-17T06:50:25.3277944Z 16.36 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3278391Z 16.36 [events-ac1] INFO src/net.rs:70: Resolved mail.ci.testrun.org:465 into 65.109.227.209:465.
2023-07-17T06:50:25.3278949Z 16.36 [events-ac1] INFO src/net.rs:70: Resolved mail.ci.testrun.org:465 into [2a01:4f9:c010:8f89::1]:465.
2023-07-17T06:50:25.3279438Z 16.50 [events-ac2] INFO src/imap/idle.rs:59: DeltaChat: Idle entering wait-on-remote state
2023-07-17T06:50:25.3279911Z 16.69 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder DeltaChat
2023-07-17T06:50:25.3280365Z 17.01 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Trash
2023-07-17T06:50:25.3280930Z 17.33 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Archive
2023-07-17T06:50:25.3281407Z 17.52 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as z4nxe@ci.testrun.org ok
2023-07-17T06:50:25.3281885Z 17.52 [events-ac1] INFO src/smtp.rs:550: Try number 1 to send message Msg#12 (entry 1) over SMTP
2023-07-17T06:50:25.3282295Z 17.52 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3282717Z 17.63 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Sent
2023-07-17T06:50:25.3283518Z 17.93 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Drafts
2023-07-17T06:50:25.3283963Z 18.24 [events-ac2] INFO src/imap.rs:540: Resync: collected 0 message IDs in folder Junk
2023-07-17T06:50:25.3284433Z 18.25 [events-ac1] INFO src/smtp/send.rs:70: Message len=1104 was SMTP-sent to yamx7@ci.testrun.org.
2023-07-17T06:50:25.3284955Z 18.25 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=1104 was SMTP-sent to yamx7@ci.testrun.org
2023-07-17T06:50:25.3285395Z 18.25 [events-ac1] DC_EVENT_MSG_DELIVERED data1=12 data2=12
2023-07-17T06:50:25.3285750Z 18.25 [events-ac1] INFO src/smtp.rs:758: Sending MDNs
2023-07-17T06:50:25.3286127Z 18.25 [events-ac1] INFO src/scheduler.rs:688: smtp fake idle - started
2023-07-17T06:50:25.3286519Z 18.25 [events-ac1] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3286970Z 18.25 [events-ac1] INFO src/scheduler.rs:710: smtp has no messages to retry, waiting for interrupt
2023-07-17T06:50:25.3287424Z 18.53 [events-ac2] INFO src/imap.rs:540: Resync: collected 1 message IDs in folder INBOX
2023-07-17T06:50:25.3287832Z 18.54 [events-ac2] INFO src/sql.rs:777: Start housekeeping...
2023-07-17T06:50:25.3288195Z 18.54 [events-ac2] INFO src/sql.rs:823: 3 files in use.
2023-07-17T06:50:25.3288550Z 18.54 [events-ac2] INFO src/sql.rs:758: Housekeeping done.
2023-07-17T06:50:25.3288919Z 18.69 [events-ac2] INFO src/imap.rs:631: Folder "Sent" is empty.
2023-07-17T06:50:25.3289319Z 19.43 [events-ac2] INFO src/imap.rs:945: Done fetching existing messages.
2023-07-17T06:50:25.3289856Z 19.57 [events-ac2] INFO src/imap.rs:773: Not moving the message Mr.XsG4aCOICeh.06nrqDxlvhx@ci.testrun.org that we have seen before.
2023-07-17T06:50:25.3290321Z 19.58 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3290752Z 19.58 [events-ac2] INFO src/imap.rs:1409: Starting a full FETCH of message set "5".
2023-07-17T06:50:25.3291189Z 19.73 [events-ac2] INFO src/imap.rs:1527: Passing message UID 5 to receive_imf().
2023-07-17T06:50:25.3291739Z 19.73 [events-ac2] INFO src/receive_imf.rs:102: Receiving message, seen=false...
2023-07-17T06:50:25.3292277Z 19.74 [events-ac2] INFO src/receive_imf.rs:142: Received message has Message-Id: Mr.XsG4aCOICeh.06nrqDxlvhx@ci.testrun.org
2023-07-17T06:50:25.3292789Z 19.74 [events-ac2] INFO src/receive_imf.rs:2105: Not creating ad-hoc group: too few contacts.
2023-07-17T06:50:25.3293272Z 19.74 [events-ac2] INFO src/receive_imf.rs:1277: Message has 1 parts and is assigned to chat #Chat#12.
2023-07-17T06:50:25.3293762Z 19.74 [events-ac2] INFO src/contact.rs:1648: Recently seen loop waiting for 0h 9m 58s or interrupt
2023-07-17T06:50:25.3294171Z 19.74 [events-ac2] DC_EVENT_CONTACTS_CHANGED data1=10 data2=0
2023-07-17T06:50:25.3294534Z 19.74 [events-ac2] DC_EVENT_INCOMING_MSG data1=12 data2=12
2023-07-17T06:50:25.3294924Z 19.74 [events-ac2] INFO src/imap.rs:1566: Successfully received 1 UIDs.
2023-07-17T06:50:25.3295315Z 19.74 [events-ac2] INFO src/imap.rs:887: 1 mails read from "INBOX".
2023-07-17T06:50:25.3295690Z 19.74 [events-ac2] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
2023-07-17T06:50:25.3296097Z 19.74 [events-ac2] INFO src/imap/scan_folders.rs:27: Starting full folder scan
2023-07-17T06:50:25.3296497Z 20.04 [events-ac2] INFO src/imap.rs:631: Folder "Junk" is empty.
2023-07-17T06:50:25.3296892Z 20.04 [events-ac2] INFO src/imap.rs:719: No new emails in folder Junk
2023-07-17T06:50:25.3297278Z 20.19 [events-ac2] INFO src/imap.rs:719: No new emails in folder Sent
2023-07-17T06:50:25.3297742Z 20.34 [events-ac2] INFO src/imap.rs:631: Folder "Archive" is empty.
2023-07-17T06:50:25.3298130Z 20.34 [events-ac2] INFO src/imap.rs:719: No new emails in folder Archive
2023-07-17T06:50:25.3298518Z 20.48 [events-ac2] INFO src/imap.rs:719: No new emails in folder INBOX
2023-07-17T06:50:25.3298900Z 20.63 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3299272Z 20.63 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2023-07-17T06:50:25.3299694Z 20.63 [events-ac2] INFO src/scheduler.rs:577: IMAP session supports IDLE, using it.
2023-07-17T06:50:25.3300445Z 20.63 [events-ac2] INFO src/imap/idle.rs:37: skip idle, got interrupt InterruptInfo { probe_network: false }
2023-07-17T06:50:25.3300882Z 20.63 [events-ac2] INFO src/job.rs:264: Loading job.
2023-07-17T06:50:25.3301356Z 20.93 [events-ac2] WARNING src/quota.rs:165: cannot get highest quota usage: no quota_resource found, this is unexpected
2023-07-17T06:50:25.3301811Z 20.93 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3302200Z 21.08 [events-ac2] INFO src/imap.rs:887: 0 mails read from "INBOX".
2023-07-17T06:50:25.3302579Z 21.23 [events-ac2] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2023-07-17T06:50:25.3302953Z 21.23 [events-ac2] DC_EVENT_IMAP_INBOX_IDLE data1=0 data2=None
2023-07-17T06:50:25.3303375Z 21.23 [events-ac2] INFO src/scheduler.rs:577: IMAP session supports IDLE, using it.
2023-07-17T06:50:25.3303828Z 21.38 [events-ac2] INFO src/imap/idle.rs:59: INBOX: Idle entering wait-on-remote state
2023-07-17T06:50:25.3304307Z ----------------------------- Captured stderr call -----------------------------
2023-07-17T06:50:25.3304528Z
2023-07-17T06:50:25.3304659Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2023-07-17T06:50:25.3304821Z
2023-07-17T06:50:25.3304955Z ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (139683065488960) ~~~~~~~~~~~~~~~~~~~~~~~
2023-07-17T06:50:25.3317907Z File "/opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/threading.py", line 890, in _bootstrap
2023-07-17T06:50:25.3318309Z self._bootstrap_inner()
2023-07-17T06:50:25.3318718Z File "/opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/threading.py", line 926, in _bootstrap_inner
2023-07-17T06:50:25.3319035Z self.run()
2023-07-17T06:50:25.3319670Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/deltachat/events.py", line 260, in run
2023-07-17T06:50:25.3320106Z event = lib.dc_get_next_event(event_emitter)
2023-07-17T06:50:25.3320484Z
2023-07-17T06:50:25.3320616Z ~~~~~~~~~~~~~~~~~~~~~~ Stack of events (139684112676416) ~~~~~~~~~~~~~~~~~~~~~~~
2023-07-17T06:50:25.3321011Z File "/opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/threading.py", line 890, in _bootstrap
2023-07-17T06:50:25.3321465Z self._bootstrap_inner()
2023-07-17T06:50:25.3321846Z File "/opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/threading.py", line 926, in _bootstrap_inner
2023-07-17T06:50:25.3322157Z self.run()
2023-07-17T06:50:25.3322717Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/deltachat/events.py", line 260, in run
2023-07-17T06:50:25.3323154Z event = lib.dc_get_next_event(event_emitter)
2023-07-17T06:50:25.3323321Z
2023-07-17T06:50:25.3323459Z ~~~~~~~~~~~~~~~~~~~~~ Stack of <unknown> (139684312933952) ~~~~~~~~~~~~~~~~~~~~~
2023-07-17T06:50:25.3324085Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/execnet/gateway_base.py", line 361, in _perform_spawn
2023-07-17T06:50:25.3324486Z reply.run()
2023-07-17T06:50:25.3325037Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/execnet/gateway_base.py", line 296, in run
2023-07-17T06:50:25.3325449Z self._result = func(*args, **kwargs)
2023-07-17T06:50:25.3326187Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/execnet/gateway_base.py", line 1049, in _thread_receiver
2023-07-17T06:50:25.3326607Z msg = Message.from_io(io)
2023-07-17T06:50:25.3327170Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/execnet/gateway_base.py", line 507, in from_io
2023-07-17T06:50:25.3327603Z header = io.read(9) # type 1, channel 4, payload 4
2023-07-17T06:50:25.3328185Z File "/home/runner/work/deltachat-core-rust/deltachat-core-rust/python/.tox/py/lib/python3.7/site-packages/execnet/gateway_base.py", line 474, in read
2023-07-17T06:50:25.3328745Z data = self._read(numbytes - len(buf))
2023-07-17T06:50:25.3328906Z
2023-07-17T06:50:25.3329034Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2023-07-17T06:50:25.3329439Z --------------------------- Captured stdout teardown ---------------------------
2023-07-17T06:50:25.3329724Z =============== ===============
2023-07-17T06:50:25.3329972Z ARCH=64 AUTHSERV_ID_CANDIDATES= BCC_SELF=0
2023-07-17T06:50:25.3330402Z BLOBDIR=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac1/dc.db-blobs
2023-07-17T06:50:25.3330794Z BOT=0 CONFIGURED_INBOX_FOLDER=INBOX CONFIGURED_MVBOX_FOLDER=DeltaChat
2023-07-17T06:50:25.3331143Z CONFIGURED_SENTBOX_FOLDER=Sent CONFIGURED_TRASH_FOLDER=Trash
2023-07-17T06:50:25.3331591Z DATABASE_DIR=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac1/dc.db
2023-07-17T06:50:25.3331950Z DATABASE_ENCRYPTED=false DATABASE_VERSION=101 DEBUG_LOGGING=0
2023-07-17T06:50:25.3332293Z DELETE_DEVICE_AFTER=0 DELETE_SERVER_AFTER=0 DELETE_TO_TRASH=<unset>
2023-07-17T06:50:25.3332656Z DELTACHAT_CORE_VERSION=v1.118.0 DISPLAY_NAME=0 DOWNLOAD_LIMIT=0 E2EE_ENABLED=1
2023-07-17T06:50:25.3333129Z ENTERED_ACCOUNT_SETTINGS=z4nxe@ci.testrun.org imap:unset:***:unset:0:Automatic:cert_strict:AUTH_NORMAL smtp:unset:0:unset:0:Automatic:cert_strict:AUTH_NORMAL
2023-07-17T06:50:25.3333546Z FETCH_EXISTING_MSGS=0 FETCHED_EXISTING_MSGS=true
2023-07-17T06:50:25.3333884Z FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=4
2023-07-17T06:50:25.3334236Z IMAP_SERVER_ID={"name": "Dovecot"} IS_CONFIGURED=1 JOURNAL_MODE=wal
2023-07-17T06:50:25.3334584Z KEY_GEN_TYPE=0 LAST_HOUSEKEEPING=1689576244 LAST_MSG_ID=0 LEVEL=awesome
2023-07-17T06:50:25.3334941Z MDNS_ENABLED=1 MEDIA_QUALITY=0 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0
2023-07-17T06:50:25.3335300Z NUM_CPUS=2 NUMBER_OF_CHAT_MESSAGES=3 NUMBER_OF_CHATS=3 NUMBER_OF_CONTACTS=1
2023-07-17T06:50:25.3335667Z ONLY_FETCH_MVBOX=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=0 QUOTA_EXCEEDING=0
2023-07-17T06:50:25.3336119Z SCAN_ALL_FOLDERS_DEBOUNCE_SECS=60 SECONDARY_ADDRS= SELFAVATAR=<unset>
2023-07-17T06:50:25.3336452Z SEND_SYNC_MSGS=0 SENTBOX_WATCH=0 SHOW_EMAILS=2 SIGN_UNENCRYPTED=0
2023-07-17T06:50:25.3336774Z SOCKS5_ENABLED=0 SQLITE_VERSION=3.39.4 UPTIME=0h 2m 30s
2023-07-17T06:50:25.3337279Z USED_ACCOUNT_SETTINGS=z4nxe@ci.testrun.org imap:z4nxe@ci.testrun.org:***:mail.ci.testrun.org:993:Ssl:cert_strict:AUTH_NORMAL smtp:z4nxe@ci.testrun.org:***:mail.ci.testrun.org:465:Ssl:cert_strict:AUTH_NORMAL
2023-07-17T06:50:25.3337749Z VERIFIED_ONE_ON_ONE_CHATS=false WEBRTC_INSTANCE=<unset>
2023-07-17T06:50:25.3338195Z --------- EMPTY FOLDERS: ['Junk', 'Drafts', 'Sent', 'Archive', 'Trash', 'DeltaChat', 'INBOX']
2023-07-17T06:50:25.3338426Z
2023-07-17T06:50:25.3338512Z =============== ===============
2023-07-17T06:50:25.3338761Z ARCH=64 AUTHSERV_ID_CANDIDATES= BCC_SELF=0
2023-07-17T06:50:25.3339174Z BLOBDIR=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac2/dc.db-blobs
2023-07-17T06:50:25.3339563Z BOT=0 CONFIGURED_INBOX_FOLDER=INBOX CONFIGURED_MVBOX_FOLDER=DeltaChat
2023-07-17T06:50:25.3339912Z CONFIGURED_SENTBOX_FOLDER=Sent CONFIGURED_TRASH_FOLDER=Trash
2023-07-17T06:50:25.3340351Z DATABASE_DIR=/tmp/pytest-of-runner/pytest-0/popen-gw3/test_move_works0/ac2/dc.db
2023-07-17T06:50:25.3340717Z DATABASE_ENCRYPTED=false DATABASE_VERSION=101 DEBUG_LOGGING=0
2023-07-17T06:50:25.3341144Z DELETE_DEVICE_AFTER=0 DELETE_SERVER_AFTER=0 DELETE_TO_TRASH=<unset>
2023-07-17T06:50:25.3341501Z DELTACHAT_CORE_VERSION=v1.118.0 DISPLAY_NAME=0 DOWNLOAD_LIMIT=0 E2EE_ENABLED=1
2023-07-17T06:50:25.3341968Z ENTERED_ACCOUNT_SETTINGS=yamx7@ci.testrun.org imap:unset:***:unset:0:Automatic:cert_strict:AUTH_NORMAL smtp:unset:0:unset:0:Automatic:cert_strict:AUTH_NORMAL
2023-07-17T06:50:25.3342374Z FETCH_EXISTING_MSGS=0 FETCHED_EXISTING_MSGS=true
2023-07-17T06:50:25.3342717Z FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=4
2023-07-17T06:50:25.3343084Z IMAP_SERVER_ID={"name": "Dovecot"} IS_CONFIGURED=1 JOURNAL_MODE=wal
2023-07-17T06:50:25.3343432Z KEY_GEN_TYPE=0 LAST_HOUSEKEEPING=1689576253 LAST_MSG_ID=0 LEVEL=awesome
2023-07-17T06:50:25.3343786Z MDNS_ENABLED=1 MEDIA_QUALITY=0 MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=1
2023-07-17T06:50:25.3344133Z NUM_CPUS=2 NUMBER_OF_CHAT_MESSAGES=3 NUMBER_OF_CHATS=3 NUMBER_OF_CONTACTS=1
2023-07-17T06:50:25.3344500Z ONLY_FETCH_MVBOX=0 PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=1 QUOTA_EXCEEDING=0
2023-07-17T06:50:25.3344851Z SCAN_ALL_FOLDERS_DEBOUNCE_SECS=60 SECONDARY_ADDRS= SELFAVATAR=<unset>
2023-07-17T06:50:25.3345196Z SEND_SYNC_MSGS=0 SENTBOX_WATCH=0 SHOW_EMAILS=2 SIGN_UNENCRYPTED=0
2023-07-17T06:50:25.3345523Z SOCKS5_ENABLED=0 SQLITE_VERSION=3.39.4 UPTIME=0h 2m 32s
2023-07-17T06:50:25.3346013Z USED_ACCOUNT_SETTINGS=yamx7@ci.testrun.org imap:yamx7@ci.testrun.org:***:mail.ci.testrun.org:993:Ssl:cert_strict:AUTH_NORMAL smtp:yamx7@ci.testrun.org:***:mail.ci.testrun.org:465:Ssl:cert_strict:AUTH_NORMAL
2023-07-17T06:50:25.3346469Z VERIFIED_ONE_ON_ONE_CHATS=false WEBRTC_INSTANCE=<unset>
2023-07-17T06:50:25.3346793Z --------- INBOX 1 messages ---------
2023-07-17T06:50:25.3347037Z Message 5 has empty body
2023-07-17T06:50:25.3347422Z --------- EMPTY FOLDERS: ['Junk', 'Drafts', 'Sent', 'Archive', 'Trash', 'DeltaChat']
2023-07-17T06:50:25.3347643Z
2023-07-17T06:50:25.3347650Z
2023-07-17T06:50:25.3347791Z 155.17 [MAIN-ac2] stop_ongoing
2023-07-17T06:50:25.3348122Z 155.17 [MAIN-ac2] dc_stop_io (stop core IO scheduler)
2023-07-17T06:50:25.3348436Z 155.17 [events-ac2] EVENT THREAD FINISHED
2023-07-17T06:50:25.3348763Z 155.17 [MAIN-ac2] wait for event thread to finish
2023-07-17T06:50:25.3349146Z 155.17 [MAIN-ac2] remove dc_context references, making the Account unusable
2023-07-17T06:50:25.3349485Z 155.17 [MAIN-ac2] shutdown finished
2023-07-17T06:50:25.3349758Z 155.32 [MAIN-ac1] stop_ongoing
2023-07-17T06:50:25.3350070Z 155.32 [MAIN-ac1] dc_stop_io (stop core IO scheduler)
2023-07-17T06:50:25.3350375Z 155.32 [events-ac1] EVENT THREAD FINISHED
2023-07-17T06:50:25.3350794Z 155.32 [MAIN-ac1] wait for event thread to finish
2023-07-17T06:50:25.3351185Z 155.32 [MAIN-ac1] remove dc_context references, making the Account unusable
2023-07-17T06:50:25.3351524Z 155.33 [MAIN-ac1] shutdown finished
2023-07-17T06:50:25.3351806Z ================== 1 failed, 172 passed in 435.83s (0:07:15) ===================
2023-07-17T06:50:25.3454956Z py: exit 1 (436.41 seconds) /home/runner/work/deltachat-core-rust/deltachat-core-rust/python> pytest -n6 --extra-info -v -rsXx --ignored --strict-tls tests examples pid=2284
2023-07-17T06:50:25.3464801Z .pkg: _exit> python /opt/hostedtoolcache/Python/3.7.17/x64/lib/python3.7/site-packages/pyproject_api/_backend.py True setuptools.build_meta
2023-07-17T06:50:25.4045181Z mypy: OK (39.81=setup[37.14]+cmd[2.67] seconds)
2023-07-17T06:50:25.4045492Z doc: OK (35.69=setup[31.34]+cmd[4.35] seconds)
2023-07-17T06:50:25.4045789Z py: FAIL code 1 (465.55=setup[29.14]+cmd[436.41] seconds)
2023-07-17T06:50:25.4046078Z evaluation failed :( (541.29 seconds)
2023-07-17T06:50:25.4372445Z ##[error]Process completed with exit code 255.
2023-07-17T06:50:25.4441366Z Post job cleanup.
2023-07-17T06:50:25.5487384Z [command]/usr/bin/git version
2023-07-17T06:50:25.5540325Z git version 2.41.0
2023-07-17T06:50:25.5585902Z Temporarily overriding HOME='/home/runner/work/_temp/71b741c8-278f-440b-b7ef-9ab6c018871d' before making global git config changes
2023-07-17T06:50:25.5587016Z Adding repository directory to the temporary git global config as a safe directory
2023-07-17T06:50:25.5592888Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/deltachat-core-rust/deltachat-core-rust
2023-07-17T06:50:25.5643683Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand
2023-07-17T06:50:25.5679597Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :"
2023-07-17T06:50:25.5943518Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2023-07-17T06:50:25.5975056Z http.https://github.com/.extraheader
2023-07-17T06:50:25.5987079Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader
2023-07-17T06:50:25.6026602Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :"
2023-07-17T06:50:25.6466393Z Cleaning up orphan processes