tests/test_multidevice.py::test_multidevice_sync_seen is flaky #7928
Description
Example of a log from CI:
2026-03-02T00:21:38.5845875Z =================================== FAILURES ===================================
2026-03-02T00:21:38.5846625Z __________________________ test_multidevice_sync_seen __________________________
2026-03-02T00:21:38.5847520Z [gw0] linux -- Python 3.10.16 /home/runner/work/core/core/deltachat-rpc-client/.tox/py/bin/python
2026-03-02T00:21:38.5848350Z
2026-03-02T00:21:38.5848805Z acfactory = <deltachat_rpc_client.pytestplugin.ACFactory object at 0x00007f2d849acd08>
2026-03-02T00:21:38.5849821Z log = <deltachat_rpc_client.pytestplugin.log.<locals>.Printer object at 0x00007f2d849acbb8>
2026-03-02T00:21:38.5850409Z
2026-03-02T00:21:38.5850610Z def test_multidevice_sync_seen(acfactory, log):
2026-03-02T00:21:38.5851348Z """Test that message marked as seen on one device is marked as seen on another."""
2026-03-02T00:21:38.5852114Z ac1, ac2 = acfactory.get_online_accounts(2)
2026-03-02T00:21:38.5852605Z ac1_clone = ac1.clone()
2026-03-02T00:21:38.5853088Z ac1_clone.bring_online()
2026-03-02T00:21:38.5853450Z
2026-03-02T00:21:38.5853751Z ac1.set_config("bcc_self", "1")
2026-03-02T00:21:38.5854218Z ac1_clone.set_config("bcc_self", "1")
2026-03-02T00:21:38.5854661Z
2026-03-02T00:21:38.5854961Z ac1_chat = ac1.create_chat(ac2)
2026-03-02T00:21:38.5855441Z ac1_clone_chat = ac1_clone.create_chat(ac2)
2026-03-02T00:21:38.5855957Z ac2_chat = ac2.create_chat(ac1)
2026-03-02T00:21:38.5856374Z
2026-03-02T00:21:38.5856853Z log.section("Send a message from ac2 to ac1 and check that it's 'fresh'")
2026-03-02T00:21:38.5857516Z ac2_chat.send_text("Hi")
2026-03-02T00:21:38.5857920Z ac1_message = ac1.wait_for_incoming_msg()
2026-03-02T00:21:38.5858726Z ac1_clone_message = ac1_clone.wait_for_incoming_msg()
2026-03-02T00:21:38.5859258Z assert ac1_chat.get_fresh_message_count() == 1
2026-03-02T00:21:38.5859772Z assert ac1_clone_chat.get_fresh_message_count() == 1
2026-03-02T00:21:38.5860354Z assert ac1_message.get_snapshot().state == MessageState.IN_FRESH
2026-03-02T00:21:38.5861029Z assert ac1_clone_message.get_snapshot().state == MessageState.IN_FRESH
2026-03-02T00:21:38.5861607Z
2026-03-02T00:21:38.5861994Z log.section("ac1 marks message as seen on the first device")
2026-03-02T00:21:38.5862539Z ac1.mark_seen_messages([ac1_message])
2026-03-02T00:21:38.5863625Z assert ac1_message.get_snapshot().state == MessageState.IN_SEEN
2026-03-02T00:21:38.5864244Z
2026-03-02T00:21:38.5864693Z log.section("ac1 clone detects that message is marked as seen")
2026-03-02T00:21:38.5868585Z ev = ac1_clone.wait_for_event(EventType.MSGS_NOTICED)
2026-03-02T00:21:38.5869188Z assert ev.chat_id == ac1_clone_chat.id
2026-03-02T00:21:38.5869601Z
2026-03-02T00:21:38.5869966Z log.section("Send an ephemeral message from ac2 to ac1")
2026-03-02T00:21:38.5872489Z ac2_chat.set_ephemeral_timer(60)
2026-03-02T00:21:38.5873043Z ac1.wait_for_event(EventType.CHAT_EPHEMERAL_TIMER_MODIFIED)
2026-03-02T00:21:38.5873613Z ac1.wait_for_incoming_msg()
2026-03-02T00:21:38.5874186Z ac1_clone.wait_for_event(EventType.CHAT_EPHEMERAL_TIMER_MODIFIED)
2026-03-02T00:21:38.5874827Z ac1_clone.wait_for_incoming_msg()
2026-03-02T00:21:38.5875221Z
2026-03-02T00:21:38.5875493Z ac2_chat.send_text("Foobar")
2026-03-02T00:21:38.5876267Z ac1_message = ac1.wait_for_incoming_msg()
2026-03-02T00:21:38.5878857Z ac1_clone_message = ac1_clone.wait_for_incoming_msg()
2026-03-02T00:21:38.5879435Z assert "Ephemeral timer: 60\n" in ac1_message.get_info()
2026-03-02T00:21:38.5880000Z assert "Expires: " not in ac1_clone_message.get_info()
2026-03-02T00:21:38.5880560Z assert "Ephemeral timer: 60\n" in ac1_message.get_info()
2026-03-02T00:21:38.5881096Z assert "Expires: " not in ac1_clone_message.get_info()
2026-03-02T00:21:38.5881530Z
2026-03-02T00:21:38.5881781Z ac1_message.mark_seen()
2026-03-02T00:21:38.5882170Z assert "Expires: " in ac1_message.get_info()
2026-03-02T00:21:38.5882696Z > ev = ac1_clone.wait_for_event(EventType.MSGS_NOTICED)
2026-03-02T00:21:38.5883057Z
2026-03-02T00:21:38.5883192Z tests/test_multidevice.py:144:
2026-03-02T00:21:38.5884785Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2026-03-02T00:21:38.5885544Z .tox/py/lib/pypy3.10/site-packages/deltachat_rpc_client/account.py:35: in wait_for_event
2026-03-02T00:21:38.5886288Z next_event = AttrDict(self._rpc.wait_for_event(self.id))
2026-03-02T00:21:38.5886977Z .tox/py/lib/pypy3.10/site-packages/deltachat_rpc_client/rpc.py:205: in wait_for_event
2026-03-02T00:21:38.5887586Z return queue.get()
2026-03-02T00:21:38.5888214Z /opt/hostedtoolcache/PyPy/3.10.16/x64/lib/pypy3.10/queue.py:171: in get
2026-03-02T00:21:38.5888781Z self.not_empty.wait()
2026-03-02T00:21:38.5889181Z _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
2026-03-02T00:21:38.5889543Z
2026-03-02T00:21:38.5889841Z self = <Condition(<unlocked _thread.lock object at 0x00007f2d849b2f98>, 0)>
2026-03-02T00:21:38.5890372Z timeout = None
2026-03-02T00:21:38.5890632Z
2026-03-02T00:21:38.5890756Z def wait(self, timeout=None):
2026-03-02T00:21:38.5891212Z """Wait until notified or until a timeout occurs.
2026-03-02T00:21:38.5891629Z
2026-03-02T00:21:38.5892027Z If the calling thread has not acquired the lock when this method is
2026-03-02T00:21:38.5892545Z called, a RuntimeError is raised.
2026-03-02T00:21:38.5892902Z
2026-03-02T00:21:38.5893341Z This method releases the underlying lock, and then blocks until it is
2026-03-02T00:21:38.5894025Z awakened by a notify() or notify_all() call for the same condition
2026-03-02T00:21:38.5894720Z variable in another thread, or until the optional timeout occurs. Once
2026-03-02T00:21:38.5895401Z awakened or timed out, it re-acquires the lock and returns.
2026-03-02T00:21:38.5895877Z
2026-03-02T00:21:38.5896269Z When the timeout argument is present and not None, it should be a
2026-03-02T00:21:38.5896977Z floating point number specifying a timeout for the operation in seconds
2026-03-02T00:21:38.5897543Z (or fractions thereof).
2026-03-02T00:21:38.5897855Z
2026-03-02T00:21:38.5898437Z When the underlying lock is an RLock, it is not released using its
2026-03-02T00:21:38.5899382Z release() method, since this may not actually unlock the lock when it
2026-03-02T00:21:38.5900102Z was acquired multiple times recursively. Instead, an internal interface
2026-03-02T00:21:38.5900802Z of the RLock class is used, which really unlocks it even when it has
2026-03-02T00:21:38.5901523Z been recursively acquired several times. Another internal interface is
2026-03-02T00:21:38.5902240Z then used to restore the recursion level when the lock is reacquired.
2026-03-02T00:21:38.5902780Z
2026-03-02T00:21:38.5903010Z """
2026-03-02T00:21:38.5903271Z if not self._is_owned():
2026-03-02T00:21:38.5903733Z raise RuntimeError("cannot wait on un-acquired lock")
2026-03-02T00:21:38.5904227Z waiter = _allocate_lock()
2026-03-02T00:21:38.5904589Z waiter.acquire()
2026-03-02T00:21:38.5904933Z self._waiters.append(waiter)
2026-03-02T00:21:38.5905344Z saved_state = self._release_save()
2026-03-02T00:21:38.5905919Z gotit = False
2026-03-02T00:21:38.5906335Z try: # restore state no matter what (e.g., KeyboardInterrupt)
2026-03-02T00:21:38.5906853Z if timeout is None:
2026-03-02T00:21:38.5907188Z > waiter.acquire()
2026-03-02T00:21:38.5907589Z E Failed: Timeout (>300.0s) from pytest-timeout.
2026-03-02T00:21:38.5907937Z
2026-03-02T00:21:38.5908412Z /opt/hostedtoolcache/PyPy/3.10.16/x64/lib/pypy3.10/threading.py:320: Failed
2026-03-02T00:21:38.5909146Z ------------------------------ Captured log setup ------------------------------
2026-03-02T00:21:38.5909832Z INFO root:rpc.py:129 RPC server ready. Core version: v2.44.0-dev
2026-03-02T00:21:38.5910503Z ----------------------------- Captured stdout call -----------------------------
2026-03-02T00:21:38.5911133Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2026-03-02T00:21:38.5911710Z ~~~~~~~~~~~~~~~~~~~~~ Stack of <unknown> (139833538758336) ~~~~~~~~~~~~~~~~~~~~~
2026-03-02T00:21:38.5920615Z File "/home/runner/work/core/core/deltachat-rpc-client/.tox/py/lib/pypy3.10/site-packages/execnet/gateway_base.py", line 411, in _perform_spawn
...
2026-03-02T00:21:38.7044874Z DEBUG root:rpc.py:194 account_id=1 got an event {'kind': 'Info', 'msg': 'src/imap/idle.rs:76: "INBOX": Received interrupt, stopping IDLE.'}
2026-03-02T00:21:38.7045295Z =========================== short test summary info ============================
2026-03-02T00:21:38.7045615Z FAILED tests/test_multidevice.py::test_multidevice_sync_seen - Failed: Timeou...
2026-03-02T00:21:38.7045823Z ============= 1 failed, 118 passed, 1 skipped in 375.72s (0:06:15) =============