fix various transport multi-device de-synchronizinzation issues by hpk42 · Pull Request #8499 · chatmail/core

hpk42 · 2026-07-31T01:19:52Z

The flakyness of test_transport_synchronization was a an unexpected treasure.
In my local cmlxc branch it failed more often than on ci chatmail server (1/15 times when running in loops IIRC).

It's best to review per commit. There is one pure test flake fix, and then actual transport-desync message related fixes in core that are likely to appear for users in the form of not properly synchronized relays.

The PR may fix the relay-desync part of #8342 and is likely related to #7835 and #7843

EDIT: General note: the contained tests do not fully exercise the fixes, because they are about concurrency issues and the rust code is done in such a way that i find it quite hard to test specific concurrency issues. FWIW I am also trying to get #7926 going final for review again, which is the branch on top of which i ran test_transport_synchronization 60 times, with it sometimes failing.

link2xt

Second and third (EDIT: maybe third commit is not needed if add_timestamp is never updated rather than always updated, see below) commits look ok, have not started reading the fourth one.

Comments are for the first one. Without an issue or at least a description of what failed (did the test timeout or did some assertion fail? where did the test fail? see #7850 and #7835 for previous debugging of the same test) it is hard to understand what the commit is fixing. There is a ConfiguredAddr config and add_timestamp timestamps, and they are somewhat independent. It is not clear if updating ConfiguredAddr failed or some other check. Also making sure add_timestamp is always increasing is fixing the tests running on a single machine, but practically likely does not help with multi-device because devices are already likely not having the clocks synchronized to one second precision.

Was the issue that the primary transport somehow did not synchronize, or the order of transports returned by list_transports was the wrong one? Which line of the test failed?
EDIT: i guess it failed with the timeout here because if add_timestamp is the same, the first event would not be emitted:

core/deltachat-rpc-client/tests/test_multitransport.py

Lines 153 to 156 in 020e477

    
           # One event for updated `add_timestamp` of the new primary transport, 
        
           # one event for the `configured_addr` update. 
        
           ac1_clone.wait_for_event(EventType.TRANSPORTS_MODIFIED) 
        
           ac1_clone.wait_for_event(EventType.TRANSPORTS_MODIFIED)

See #8499 (comment) below, maybe we should make sure it is never emitted rather than always emitted? I think the only reason for bumping add_timestamp is to change the order of the relays in the public key, but if we send up to 5 relays and take up to 5 relays, the order should not matter.

link2xt · 2026-07-31T04:49:12Z

+    // other devices ignore the change otherwise.
+    assert!(add_timestamp(alice2, addr).await > old_timestamp);
+    assert_eq!(
+        alice2.get_config(Config::ConfiguredAddr).await?.as_deref(),


Was this already working without increasing add_timestamp? Here is the code that updates the primary transport, it only checks if the transport exists:

core/src/receive_imf.rs

Lines 802 to 830 in 020e477

let transport_changed = context

.sql

.transaction(|transaction| {

let transport_exists = transaction.query_row(

"SELECT COUNT(*) FROM transports WHERE addr=?",

(from_addr,),

|row| {

let count: i64 = row.get(0)?;

Ok(count > 0)

},

)?;

let transport_changed = if transport_exists {

transaction.execute(

"

UPDATE config SET value=? WHERE keyname='configured_addr' AND value!=?1

",

(from_addr,),

)? > 0

} else {

warn!(

context,

"Received sync message from unknown address {from_addr:?}."

);

false

};

Ok(transport_changed)

})

.await?;

link2xt · 2026-07-31T04:59:22Z

+
+    // add_timestamp must monotonically increase because
+    // other devices ignore the change otherwise.
+    assert!(add_timestamp(alice2, addr).await > old_timestamp);


SQL is now changed to increase add_timestamp at least by 1, and the test is checking that add_timestamp is increased.

I have checked out the branch, split the first commit into the test changes and the fix, commented out two add_timestamp asserts and the test passes. So ConfiguredAddr is already synchronized even without the changes to add_timestamp.

SQL is now changed to increase add_timestamp at least by 1, and the test is checking that add_timestamp is increased.

add_timestamp only increases by 1 if the clock hasn't advanced beyond the current transport timestamps.
the same-second test is meant to test that.

link2xt · 2026-07-31T05:52:23Z

Maybe we should not update add_timestamp at all when changing the primary transport? Then there will consistently be no "transports modified" events related to bumping add_timestamp. The only downside is that get_published_self_addrs will not be reordered when switching the primary transport, but with the overall limit on the published relay number we should send all published relays in the key and accept the same number, so the order of relay addresses advertised in the key will not matter. I made #8501 with the proposed change, I think it makes sense in any case.

link2xt · 2026-07-31T06:14:53Z

                            transaction
                                .execute(
-                                    "UPDATE transports SET add_timestamp=?, is_published=1 WHERE addr=?",
+                                    "UPDATE transports


So my suggestion is to remove this block (with large comment about get_all_self_addrs) completely, and only update the configured_addrs and still send the sync message, but with unchanged addresses. And then expect only a single event on the other side. This does not depend on #8501 and we are anyway going to only add up to 3 relays with automatic relay management.

I think we need to keep is_published=1 for promoting an unpublished transport

even then, test_is_published_flag fails in the final check_addrs without increasing timestamp. As far as i see merge_openpgp_certificates depends on timestamps increasing, or it will keep the stored cert with signature timestamp being the max of transport/removed_transports timestamps.

sidenote: i think all transport manipulation should be done in transport.rs and tested there, and other sites only use it. This would make it easier i think to get a complete picture and certainty that it handles all cases. But that's clearly outside this PR.

fwiw, i also pushed a revised and shortened comment block.

Without the fix, too fast transport changes are ignored at the receiver side.

…essage Uncaching only after send_sync_transports() could send the sync message from the old primary address, so other devices never switched.

…_addr

…ellation Came across this while investigating more test_transport_synchronization flakiness, sometimes missing TransportsModified events or getting a missing configured_addr. The underlying problem was that stopping IO was triggered immediately during receiving sync messages, potentially *canceling* the processing of the sync message, effectively de-syncing the device's view on transports.

Hocuri

Same as @link2xt, I think that the two middle commits are good, ~~first and~~ last commit look unclear why it helps. I commented only on the last commit, because @link2xt already commented on the first one ~~and because the first commit might be superflous if we remove primary transport synchronization~~

Edit: I was mistaken in part of my comment here, see @link2xt's comment below

Hocuri · 2026-07-31T18:29:45Z

+    if ctx.restart_io_after_fetch.swap(false, Ordering::Relaxed) {
+        // Stopping IO from within the inbox loop would cancel it.
+        task::spawn(restart_io_if_running_boxed(ctx.clone()));
+    }


TL;DR: This won't solve the flakiness completely, it can just make it smaller (even though I didn't understand yet why restarting IO causes this problem at all). I have ideas for a proper solution, but they are bigger changes. If the fix here noticeably improves test flakiness, then it might be fine for now as a partial solution.

The underlying problem was that stopping IO was triggered immediately during
receiving sync messages, potentially canceling the processing of the sync message,
effectively de-syncing the device's view on transports.

I'm afraid that we still have this problem, it might just happen less frequently (I didn't test whether it does). If one transport sets restart_io_after_fetch, and a second transport enters idle shortly afterwards, then the second transport will see that restart_io_after_fetch is set, and restart io, even the first transport isn't done with processing the message yet. A partial solution to this would be to make restart_io_after_fetch per-transport, but that's not trivial because sync_transports() doesn't have access to Imap or Session, and we would still have the problem that restarting IO at a bad time might cause problems.

I didn't really understand yet why restarting IO causes problems at all, because ~~if the message isn't completely processed, then it's not written into the database, so that it should be downloaded again.~~ restart_io_if_running_boxed() is called after applying the sync. But this might just be an incomplete understanding of the complex interactions of restarting and cancelling, and also we do handle some things (unrelated to transport sync) after writing the message into the database, so that I totally see how restarting at a bad timing can be a problem.

The complete solution to protect against stops or restarts at a bad timing would be to prevent cancellation during receive_imf(). There are two possibilities for this:

In the IMAP loop: Rather than cancelling and dropping the future (by using cancelled() and race(fut)), periodically call is_cancelled(), and return if it returns true.

Make SQL calls non-async by using non-async Mutexes and Rwlocks structs (i.e. the ones from std rather than tokio). We're already using block_in_place() to wrap the calls to sqlite, we would just need to expand its scope to also wrap any calls to lock(), read(), write(). I'm not sure if that would actually work, but in this way, the whole of receive_imf()` would become non-async. Then, it couldn't be cancelled in the middle but would just run to completion when the future is dropped.

Then again, a partial solution is better than no solution, and if this change removes the apparent test flakiness, then it might still be an improvement, even though the test is probably just less flaky rather than being actually stable.

In the IMAP loop: Rather than cancelling and dropping the future (by using cancelled() and race(fut)), periodically call is_cancelled(), and return if it returns true.

Even if we stop racing against cancelled(), scheduler may still cancel the inbox loop with a timeout if shutting down takes too long, and we want to eventually shutdown the inbox loop e.g. if the connection is very slow and the inbox loop is stuck downloading the message for hours.

Ideally most async code should be cancellation-safe with rare exceptions marked as such. If cancelling IMAP loop at the wrong moment results in some message never being downloaded, it is a bug somewhere down the IMAP loop code, e.g. if we record somewhere that the message is downloaded before running receive_imf to completion.

it is a bug somewhere down the IMAP loop code, e.g. if we record somewhere that the message is downloaded before running receive_imf to completion.

I mean, we do: We call INSERT INTO msgs towards the end of add_parts(), and there are quite some things we do afterwards (non-exhaustive list):

unarchive the chat if needed

promote the chat if needed

apply pending reactions to the message

update the contact's last_seen

save attached locations

Execute sync items

receive webxdc status updates

apply changes to the user avatar and status

If we decide to make receive_imf() non-async (see my last comment for how this could be done), then it would be possible to put the whole of receive_imf() into one SQL transaction by using a thread-local transaction variable, and using it in Sql::call() if it's set. Today we can't do that because we can't hold a transaction over an await point. I'm not sure whether this actually works and is a good idea, though.

TL;DR: This won't solve the flakiness completely, it can just make it smaller (even though I didn't understand yet why restarting IO causes this problem at all).

here is the problem with main as i see it:

a sync message is in add_parts() persistently assigned to trash before execute_sync_items executes.

cancellation within that function is triggered immediately and occurs at any subsequent async point

the message gets refetched but not processed because it exists as RFC724_mid

This leads to the flakyness of one or two TransportsModified events that i observed. If you insert a sleep after execute_sync_items you can more reliably cause the problem. It's some kind of direct self-sabotage.

Regular messages also don't get re-processed after add_parts() but the most important work regarding sync messages happens later. Therefore, UID_NEXT not progressing (because job is canceled) doesn't help.

You are right that Transport A and B concurrently fetching might cancel each other's message receiving mid-flight, But in the current code path, the only place that triggers concurrent cancellation from within receive_imf is kind of guaranteed to cause troubles every Nth time with N not being very large. Corrupting sync processing especially when multi-device&multi-relay already have their own flakyness problems without it, is .... i think worthwhile to avoid as much as we can. By comparison, Transport A randomly stopping something in Transport B is not good, but usually not as critical. Regular text messages are after add_parts() there and user-visible, even if all post-processing fails: you might loose a reaction, or an MDN or an avatar or webxdc update or so. But as far as i see, none of them are as serious as somewhat predictably corrupting multi-relay/device state.

link2xt · 2026-07-31T18:51:57Z

first and last commit look unclear why they help

First commit (i have not reviewed the last one) helps with the flaky test by making sure two "transports modified" events are always emitted when the primary transport is changed.

Generally making sure add_timestamp is always increasing helps with the tests and in case of many changes happening to the same transport at once, but only as long as the changes happen on the same device.

and because the first commit might be superflous if we remove primary transport synchronization

See the comment at #8499 (comment), it is not only about primary transport synchronization, but also publishing/unpublishing relays.

If we say that relays can never be unpublished, then it will be easier as relays will go through the states published -> unpublished -> removed. Making sure that we always increase add_timestamp when unpublishing the relay will help in the corner case when the relay is added and immediately unpublished, or when the relay was added on a device with the clock that is in the future.

If we agree that publishing previously unpublished relay should never happen, then we can say that is_published=0 takes precedence over is_published=1 regardless of add_timestamp. Then add_timestamp will only matter for configuration update, e.g. changing the password for existing address.

Hocuri · 2026-07-31T19:20:13Z

If we agree that publishing previously unpublished relay should never happen

We didn't talk yet about the mechanism for removing and replacing relays. Do we ever want to automatically re-publish a relay if it turns out to be working again? I'm unsure which way we should decide.

We do not need to worry about a user option to re-publish a previously unpublished relay.

Hocuri · 2026-07-31T19:25:11Z

If the first commit fixes a test flakiness, then from my side it's good as-is; it looks sensible enough.

hpk42 · 2026-07-31T20:20:02Z

If we agree that publishing previously unpublished relay should never happen

We didn't talk yet about the mechanism for removing and replacing relays. Do we ever want to automatically re-publish a relay if it turns out to be working again? I'm unsure which way we should decide.

We do not need to worry about a user option to re-publish a previously unpublished relay.

To me more interesting than such a policy discussion is making setting primary relays a local operation without any sync messages. A "local_reelect_primary()" function can easily be tested against various transport/configured_addr input, for example: if the only remaining relays are unpublished (for whatever reason) still elect one as primary, to have a chance to send out messages. Reelection just selects the "best", and if you only have a broken single unpublished relay, than it's the best at hand. Hopefully some other upcoming checks will figure out it's time to setup a new relay, and tell all the otherwise stranded contacts about, before or after removing the broken one :)

	# One event for updated `add_timestamp` of the new primary transport,
	# one event for the `configured_addr` update.
	ac1_clone.wait_for_event(EventType.TRANSPORTS_MODIFIED)
	ac1_clone.wait_for_event(EventType.TRANSPORTS_MODIFIED)

	let transport_changed = context
	.sql
	.transaction(\|transaction\| {
	let transport_exists = transaction.query_row(
	"SELECT COUNT(*) FROM transports WHERE addr=?",
	(from_addr,),
	\|row\| {
	let count: i64 = row.get(0)?;
	Ok(count > 0)
	},
	)?;

	let transport_changed = if transport_exists {
	transaction.execute(
	"
	UPDATE config SET value=? WHERE keyname='configured_addr' AND value!=?1
	",
	(from_addr,),
	)? > 0
	} else {
	warn!(
	context,
	"Received sync message from unknown address {from_addr:?}."
	);
	false
	};
	Ok(transport_changed)
	})
	.await?;

Uh oh!

Uh oh!

Conversation

hpk42 commented Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

link2xt left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

link2xt commented Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Hocuri left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Hocuri Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Hocuri Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Hocuri Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

link2xt commented Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Hocuri commented Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Hocuri commented Jul 31, 2026

Uh oh!

hpk42 commented Jul 31, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

hpk42 commented Jul 31, 2026 •

edited

Loading

link2xt left a comment •

edited

Loading

link2xt commented Jul 31, 2026 •

edited

Loading

Hocuri left a comment •

edited

Loading

Hocuri Jul 31, 2026 •

edited

Loading

Hocuri Jul 31, 2026 •

edited

Loading

Hocuri Jul 31, 2026 •

edited

Loading

link2xt commented Jul 31, 2026 •

edited

Loading

Hocuri commented Jul 31, 2026 •

edited

Loading

hpk42 commented Jul 31, 2026 •

edited

Loading