Stuck on Updating... after changing profile picture. #6656

dillfrescott · 2025-03-12T20:33:55Z

I'm just using the latest version for flatpak on ubuntu. But this also happened on windows version as well before.

If I'm using my phone and computer on the same profile, and I change my profile picture on one device they become out of sync and one device says updating... forever. and closing and opening the app doesn't fix it.

It also cannot receive messages.

dillfrescott · 2025-03-12T20:36:31Z

it seems like it will sometimes say connected again after a long while of waiting. It also could have been me sending a message to someone from the working device that jump started it. Either way its still a weird and annoying issue.

nicodh · 2025-03-13T09:00:58Z

I could reproduce this:

change profile image on one device
send a message from another device
the device with changed profile hangs "Connecting"

This happens with Adroid 1.54.3 and Desktop 1.54.2 (even on master with newest core 1.157.1)

After 1-2 minutes the connection works again, even without any other activity

nicodh · 2025-03-13T09:17:12Z

This is a complete log after changing the profile image and sending a message to SELF chat from the other device:

36.4s [D]core/event: 2 AccountsItemChanged { kind: 'AccountsItemChanged' }
36.4s [D]core/event: 2 ConfigSynced { key: 'selfavatar', kind: 'ConfigSynced' }
36.5s [i]core/event: 2 src/imap/idle.rs:77: "INBOX": Received interrupt, stopping IDLE.
36.5s [i]core/event: 2 src/imap/idle.rs:92: "INBOX": Idle wait was interrupted manually.
36.5s [D]core/event: 2 AccountsItemChanged { kind: 'AccountsItemChanged' }
36.6s [D]core/event: 2 ConfigSynced { key: 'displayname', kind: 'ConfigSynced' }
36.6s [D]core/event: 2 ConfigSynced { key: 'selfstatus', kind: 'ConfigSynced' }
36.6s [i]core/event: 2 src/ephemeral.rs:609: Ephemeral loop waiting for deletion in 24h 0m 0s or interrupt

account changed ( 60 seconds without log entries)

96.4s [w]core/event: 2 /build/source/src/scheduler.rs:577: fetch_idle: send_sync_msgs: IMAP APPEND to INBOX failed for Msg#34: io: timed out: timed out
96.4s [w]core/event: 2 src/scheduler.rs:418: Failed fetch_idle: fetch_move_delete: fetch_new_messages: prefetch: io: timed out: timed out
96.4s [i]core/event: 2 src/imap.rs:327: Connecting to IMAP server
96.4s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
96.4s [i]core/event: 2 src/imap.rs:342: IMAP trying to connect to nine.testrun.org:443:tls.
96.4s [i]core/event: 2 src/net/dns.rs:133: Using memory-cached DNS resolution for nine.testrun.org.
96.4s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 37.218.247.14.
96.4s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 116.202.233.236.
96.4s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 2a01:4f8:241:4ce8::2.
96.4s [i]core/event: 2 src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (116.202.233.236:443).
96.5s [i]core/event: 2 src/imap.rs:379: Logging into IMAP server with LOGIN.
96.6s [i]core/event: 2 src/imap.rs:388: Enabling IMAP compression.
96.6s [D]core/event: 2 ImapConnected {
  kind: 'ImapConnected',
  msg: 'IMAP-LOGIN as [email protected]'
}
96.6s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
96.6s [i]core/event: 2 src/imap.rs:411: Successfully logged into IMAP server
96.6s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }

connected to IMAP but message is not received ( another 60 seconds without log entries)

156.7s [w]core/event: 2 src/scheduler.rs:418: Failed fetch_idle: fetch_move_delete: fetch_new_messages: Failed to select folder "INBOX": IMAP other error: failed to select folder INBOX: IMAP other error: io: timed out
156.7s [i]core/event: 2 src/imap.rs:327: Connecting to IMAP server
156.7s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
156.7s [i]core/event: 2 src/imap.rs:342: IMAP trying to connect to nine.testrun.org:443:tls.
156.7s [i]core/event: 2 src/net/dns.rs:133: Using memory-cached DNS resolution for nine.testrun.org.
156.7s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 37.218.247.14.
156.7s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 116.202.233.236.
156.8s [i]core/event: 2 src/net/dns.rs:179: Resolved nine.testrun.org into 2a01:4f8:241:4ce8::2.
156.8s [i]core/event: 2 src/imap/client.rs:122: Attempting IMAP connection to nine.testrun.org (116.202.233.236:443).
156.8s [i]core/event: 2 src/imap.rs:379: Logging into IMAP server with LOGIN.
156.9s [i]core/event: 2 src/imap.rs:388: Enabling IMAP compression.
156.9s [D]core/event: 2 ImapConnected {
  kind: 'ImapConnected',
  msg: 'IMAP-LOGIN as [email protected]'
}
156.9s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
156.9s [i]core/event: 2 src/imap.rs:411: Successfully logged into IMAP server
156.9s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
157s [i]core/event: 2 src/imap.rs:632: Not moving the message e18ec6d6-4c77-4181-a7ab-7cf53404d5dc@localhost that we have seen before.
157s [D]core/event: 2 ConnectivityChanged { kind: 'ConnectivityChanged' }
157s [i]core/event: 2 src/imap.rs:1353: Starting a full FETCH of message set "15".
157s [i]core/event: 2 src/imap.rs:1464: Passing message UID 15 to receive_imf().
157s [i]core/event: 2 src/receive_imf.rs:226: Receiving message "2fb82fce-e2ba-4ab4-a0e5-566bc65bf5e3@localhost", seen=true...

now the message is fetched

nicodh · 2025-03-13T09:21:33Z

Also tested with core 1.157.1 (on Desktop master)

nicodh · 2025-03-13T09:45:44Z

I'm just using the latest version for flatpak on ubuntu. But this also happened on windows version as well before.

If I'm using my phone and computer on the same profile, and I change my profile picture on one device they become out of sync and one device says updating... forever. and closing and opening the app doesn't fix it.

It also cannot receive messages.

How long does this state last? I can reproduce it but after 1-2 minutes the connection is up again.

dillfrescott · 2025-03-13T11:46:32Z

It would appear the duration can vary? Although I havent tested it enough to be sure!

dillfrescott · 2025-03-13T13:35:49Z

I dont know if its a deltachat app issue or a chatmail server bug

WofWca · 2025-03-13T13:53:26Z

Could #6477 be related?

dillfrescott · 2025-03-13T14:32:55Z

I dont know. Sounds like it could be though!

link2xt · 2025-03-13T22:29:34Z

Possibly related: #6526

EDIT: I tested, reverting #6526 does not fix the test reproducing the issue in #6658

link2xt · 2025-03-13T23:27:58Z

Uploading avatar via IMAP append also fails in #6658

The log line is similar to DC desktop 96.4s [w]core/event: 2 /build/source/src/scheduler.rs:577: fetch_idle: send_sync_msgs: IMAP APPEND to INBOX failed for Msg#34: io: timed out: timed out

Forcefully disabling IMAP compress here "fixes" the issue:

core/src/imap.rs

Line 387 in 82f6103

let session = if capabilities.can_compress {

This probably explains why the issue does not appear for @Hocuri with gmx.net at #6658, if gmx.net does not support IMAP COMPRESS.

This looks like some buffering issue, compressed stream is likely not flushed properly and uploading the sync message via IMAP APPEND times out eventually.

link2xt · 2025-03-13T23:37:37Z

There was a recent fix Nullus157/async-compression#327 in async-compression 0.4.19. We are currently using async-compression 0.4.18.

dillfrescott · 2025-03-13T23:39:09Z

Wow good job finding the issue!

link2xt · 2025-03-13T23:44:14Z

Updating async-compression to 0.4.20 did not fix the issue, so more debugging is needed. I also tested that downgrade to 0.4.16 does not help. It still times out even though we do the flushing on our side in async-imap right after sending APPEND command down the stream.

Still get this:

DEBUG    root:rpc.py:174 account_id=1 got an event {'kind': 'Warning', 'msg': '/home/user/src/chatmail/core/src/imap.rs:1108: IMAP APPEND to INBOX failed for Msg#13: io: timed out: timed out'}

APPEND "INBOX" (\Seen) {12019} is flushed properly, then we get + OK response.

Then in async-imap we write the 12019-byte long message and flush the stream:
https://github.com/chatmail/async-imap/blob/b37821fd193c4d09bc212b062a012f0688b1f18c/src/client.rs#L1142-L1144

But then this check_done_ok call eventually times out:
https://github.com/chatmail/async-imap/blob/b37821fd193c4d09bc212b062a012f0688b1f18c/src/client.rs#L1145-L1147

Normally protocol looks like this:

A9999 APPEND "INBOX" (\Seen) {10}
+ OK
1234567890
A9999 OK [APPENDUID 1741911362 2] Append completed (0.052 + 2.519 + 0.050 secs).

On the testing email server nothing got appended into INBOX, all maildirs are empty, so flushing likely did not work out. It is not the issue with reading the response, I don't think there is any response sent as nothing was uploaded.

link2xt · 2025-03-14T00:35:08Z

Wonder if #6611 is related, we previously sent smaller avatars around.

link2xt · 2025-03-14T01:39:37Z

I tried truncating uploaded over IMAP APPEND message and it gets flaky around 11085 bytes:

11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11086 success
11087 fail
11086 fail
11085 fail
11084 fail
11084 success

Probably also depends on the exact image uploaded and how well it compresses. I used the test in #6658

link2xt · 2025-03-14T02:04:18Z

This is also not a Rustls bug. I tested with imap_certificate_checks set to 2, the bug is the same when using OpenSSL.

link2xt · 2025-03-14T02:34:46Z

The test passes if I change this line to const DEFAULT_BUF_SIZE: usize = 16384;:
https://github.com/Nullus157/async-compression/blob/f3e97421bbb1d5ad9f337673c8721f11fb57a06c/src/tokio/write/buf_writer.rs#L16
This is not a fix of course, just a hack to verify that it is a sender buffering issue.

So it is likely a bug in async-compression. When IMAP COMPRESS was introduced I had to fix the receiver part, porting a bugfix from futures to tokio implementation: Nullus157/async-compression#294
But we did not have any troubles with the compression side so I have not looked into the compression part before.

link2xt · 2025-03-14T03:29:27Z

Even with buffer reduced to 256, this poll_write call on the encoder (public API of async-compression used by async-imap) immediately consumes everything and returns Ready(Ok(12019)), followed by Ready(Ok(2)) for the next call writing \r\n. This means flate2 encoder consumed the whole input in one go, but because output buffer is small, it can only produce 256 bytes of compressed data. The rest should be flushed out of the encoder state during the flush call, but this does not happen.

link2xt · 2025-03-14T04:05:45Z

I made a fix at Nullus157/async-compression#333

link2xt · 2025-03-15T08:32:58Z

PR updating async-compression: #6666

…d device (#6657) Found and fixed a bug while investigating #6656. It's not the same bug, though. Steps to reproduce this bug: - Create a new profile - Transfer it to a second device - Send a message from the first device - -> It will never arrive on the second device, instead a warning will be printed that you are using DC on multiple devices. The bug was that the key wasn't created before the backup transfer, so that the second device then created its own key instead of using the same key as the first device. In order to regression-test, this PR now changes `clone()` to use "Add second device" instead of exporting and importing a backup. Exporting and importing a backup has enough tests already. This PR also adds an unrelated test `test_selfavatar_sync()`. The bug was introduced by #6574 in v1.156.0

nicodh added the bug Something is not working label Mar 13, 2025

Hocuri transferred this issue from deltachat/deltachat-desktop Mar 13, 2025

Hocuri transferred this issue from deltachat/issue-stargate Mar 13, 2025

Hocuri self-assigned this Mar 13, 2025

This was referenced Mar 13, 2025

fix: Fix setting up a profile and immediately transferring to a second device #6657

Merged

[WIP] test: Add a test for selfavatar-sync #6658

Merged

Hocuri removed their assignment Mar 13, 2025

This was referenced Mar 14, 2025

fix(flate encoder): do not mark internal state as flushed if we ran out of buffer space Nullus157/async-compression#333

Merged

fix: update async-compression to 0.4.21 to fix IMAP COMPRESS getting stuck #6666

Merged

link2xt mentioned this issue Mar 15, 2025

Update core to 1.157.2 deltachat/deltachat-desktop#4780

Merged

link2xt closed this as completed in #6666 Mar 15, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stuck on Updating... after changing profile picture. #6656

Stuck on Updating... after changing profile picture. #6656

dillfrescott commented Mar 12, 2025

dillfrescott commented Mar 12, 2025

nicodh commented Mar 13, 2025 •

edited

Loading

nicodh commented Mar 13, 2025

nicodh commented Mar 13, 2025

nicodh commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

WofWca commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

link2xt commented Mar 13, 2025 •

edited

Loading

link2xt commented Mar 13, 2025

link2xt commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

link2xt commented Mar 13, 2025 •

edited

Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025 •

edited

Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025 •

edited

Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 15, 2025

Stuck on Updating... after changing profile picture. #6656

Stuck on Updating... after changing profile picture. #6656

Comments

dillfrescott commented Mar 12, 2025

dillfrescott commented Mar 12, 2025

nicodh commented Mar 13, 2025 • edited Loading

nicodh commented Mar 13, 2025

nicodh commented Mar 13, 2025

nicodh commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

WofWca commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

link2xt commented Mar 13, 2025 • edited Loading

link2xt commented Mar 13, 2025

link2xt commented Mar 13, 2025

dillfrescott commented Mar 13, 2025

link2xt commented Mar 13, 2025 • edited Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025 • edited Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025

link2xt commented Mar 14, 2025 • edited Loading

link2xt commented Mar 14, 2025

link2xt commented Mar 15, 2025

nicodh commented Mar 13, 2025 •

edited

Loading

link2xt commented Mar 13, 2025 •

edited

Loading

link2xt commented Mar 13, 2025 •

edited

Loading

link2xt commented Mar 14, 2025 •

edited

Loading

link2xt commented Mar 14, 2025 •

edited

Loading