search

deltachat / deltachat-core-rust

Delta Chat Rust Core library, used by Android/iOS/desktop apps, bindings and bots 📧
https://delta.chat/en/contribute
Other
669 stars 85 forks source link

Messages moved to DeltaChat folder on Mailcow instance received in wrong order #5339

Open link2xt opened 8 months ago

link2xt commented 8 months ago

We recently had a problem with two messages received in wrong order: "member added" message and following editor.xdc message.

Two messages received by c@testrun.org running Delta Chat Android version 1.42.6 (core 1.131.9) were processed in the wrong order:

  1. Member added message, a@example.org adds c@testrun.org: 
    
Sent: 2024-03-06 09:51:21 (1709715081000) by a@example.org
Received: 2024-03-06 12:33:57 (1709724837000)

</DeltaChat/;UID=193>

messageId 234


2. Editor XDC message b@example.de sent to the group:

Sent: 2024-03-06 11:44:37 (1709721877000) by b@example.de Received: 2024-03-06 12:33:51 (1709724831000)

File: .../dc.db-blobs/Editor.xdc, 151583 bytes

</DeltaChat/;UID=194> </INBOX/;UID=101> </INBOX/;UID=110> </INBOX/;UID=241>

messageId 224



INBOX UIDs on the second message are resent messages not moved due to <https://github.com/deltachat/deltachat-core-rust/issues/5155>, this bug was fixed in core 1.134.0.

The problem is that message 1 with UID 193 was processed later than message 2 with UID 194. Second message got messageId 224 (this is a database row ID) and first message got messageId 234.

This reordering is unlikely to be due to partial message download because it is disabled by default and because `rcvd_timestamp` of messages is too close.

Delta Chat sorts messages by INTERNALDATE:
https://github.com/deltachat/deltachat-core-rust/blob/76bbd5fd72dff1591b4861431e028879bfa9177f/src/imap/session.rs#L157

testrun.org runs Mailcow (Dovecot), so it looks like INTERNALDATE gets changed when a batch of messages are moved to DeltaChat folder.
link2xt commented 8 months ago

I have tested with nine.testrun.org which also runs Dovecot, there moving the messages did not change INTERNALDATE:

1 OK [CAPABILITY IMAP4rev1 IDLE MOVE QUOTA CONDSTORE NOTIFY METADATA XDELTAPUSH] Logged in
1 SELECT INBOX
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
* 10 EXISTS
* 10 RECENT
* OK [UNSEEN 1] First unseen.
* OK [UIDVALIDITY 1710468796] UIDs valid
* OK [UIDNEXT 11] Predicted next UID
1 OK [READ-WRITE] Select completed (0.003 + 0.000 + 0.002 secs).
? UID FETCH 1:10 (UID INTERNALDATE)
* 1 FETCH (UID 1 INTERNALDATE "15-Mar-2024 03:13:16 +0100")
* 2 FETCH (UID 2 INTERNALDATE "15-Mar-2024 03:13:20 +0100")
* 3 FETCH (UID 3 INTERNALDATE "15-Mar-2024 03:13:21 +0100")
* 4 FETCH (UID 4 INTERNALDATE "15-Mar-2024 03:13:22 +0100")
* 5 FETCH (UID 5 INTERNALDATE "15-Mar-2024 03:13:22 +0100")
* 6 FETCH (UID 6 INTERNALDATE "15-Mar-2024 03:13:24 +0100")
* 7 FETCH (UID 7 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 8 FETCH (UID 8 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 9 FETCH (UID 9 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 10 FETCH (UID 10 INTERNALDATE "15-Mar-2024 03:13:35 +0100")
? OK Fetch completed (0.004 + 0.000 + 0.003 secs).
? UID MOVE 1:10 DeltaChat
? NO [TRYCREATE] Mailbox doesn't exist: DeltaChat (0.001 + 0.000 secs).
? CREATE "DeltaChat"
? OK Create completed (0.040 + 0.000 + 0.039 secs).
? UID MOVE 1:10 DeltaChat
* OK [COPYUID 1710468797 1:10 1:10] Moved UIDs.
* 10 EXPUNGE
* 9 EXPUNGE
* 8 EXPUNGE
* 7 EXPUNGE
* 6 EXPUNGE
* 5 EXPUNGE
* 4 EXPUNGE
* 3 EXPUNGE
* 2 EXPUNGE
* 1 EXPUNGE
* 0 RECENT
? OK Move completed (0.044 + 0.000 + 0.043 secs).
? SELECT DeltaChat
* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
* 10 EXISTS
* 10 RECENT
* OK [UNSEEN 1] First unseen.
* OK [UIDVALIDITY 1710468797] UIDs valid
* OK [UIDNEXT 11] Predicted next UID
? OK [READ-WRITE] Select completed (0.002 + 0.000 + 0.001 secs).
? UID FETCH 1:10 (UID INTERNALDATE)
* 1 FETCH (UID 1 INTERNALDATE "15-Mar-2024 03:13:16 +0100")
* 2 FETCH (UID 2 INTERNALDATE "15-Mar-2024 03:13:20 +0100")
* 3 FETCH (UID 3 INTERNALDATE "15-Mar-2024 03:13:21 +0100")
* 4 FETCH (UID 4 INTERNALDATE "15-Mar-2024 03:13:22 +0100")
* 5 FETCH (UID 5 INTERNALDATE "15-Mar-2024 03:13:22 +0100")
* 6 FETCH (UID 6 INTERNALDATE "15-Mar-2024 03:13:24 +0100")
* 7 FETCH (UID 7 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 8 FETCH (UID 8 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 9 FETCH (UID 9 INTERNALDATE "15-Mar-2024 03:13:34 +0100")
* 10 FETCH (UID 10 INTERNALDATE "15-Mar-2024 03:13:35 +0100")
? OK Fetch completed (0.002 + 0.000 + 0.001 secs).

Unselecting and reselecting the folder to clear \Recent flags as well as setting \Seen flags did not result in changing of INTERNALDATE as well. This is correct and corresponds to IMAP4rev1 RFC: https://www.rfc-editor.org/rfc/rfc3501#page-12

link2xt commented 8 months ago

I have looked at my INBOX on testrun.org (I do not move messages to DeltaChat folder) and there seems to be some problem in INTERNALDATE timestamping on that day, see UID 181201 and UID 181202 having weird timestamps)

? UID FETCH 181191:181209 (UID INTERNALDATE)
* 8379 FETCH (UID 181191 INTERNALDATE "06-Mar-2024 16:52:32 +0100")
* 8380 FETCH (UID 181192 INTERNALDATE "06-Mar-2024 16:54:37 +0100")
* 8381 FETCH (UID 181193 INTERNALDATE "06-Mar-2024 16:54:41 +0100")
* 8382 FETCH (UID 181194 INTERNALDATE "06-Mar-2024 17:03:04 +0100")
* 8383 FETCH (UID 181195 INTERNALDATE "06-Mar-2024 17:03:09 +0100")
* 8384 FETCH (UID 181196 INTERNALDATE "06-Mar-2024 17:03:28 +0100")
* 8385 FETCH (UID 181197 INTERNALDATE "06-Mar-2024 17:03:58 +0100")
* 8386 FETCH (UID 181198 INTERNALDATE "06-Mar-2024 17:05:25 +0100")
* 8387 FETCH (UID 181199 INTERNALDATE "06-Mar-2024 17:09:09 +0100")
* 8388 FETCH (UID 181200 INTERNALDATE "06-Mar-2024 17:10:16 +0100")
* 8389 FETCH (UID 181201 INTERNALDATE "06-Mar-2024 10:42:05 +0100")
* 8390 FETCH (UID 181202 INTERNALDATE "06-Mar-2024 13:57:32 +0100")
* 8391 FETCH (UID 181203 INTERNALDATE "06-Mar-2024 17:26:43 +0100")
* 8392 FETCH (UID 181204 INTERNALDATE "06-Mar-2024 17:27:01 +0100")
* 8393 FETCH (UID 181205 INTERNALDATE "06-Mar-2024 17:28:27 +0100")
* 8394 FETCH (UID 181206 INTERNALDATE "06-Mar-2024 17:30:27 +0100")
* 8395 FETCH (UID 181207 INTERNALDATE "06-Mar-2024 17:30:33 +0100")
* 8396 FETCH (UID 181208 INTERNALDATE "06-Mar-2024 17:32:36 +0100")
* 8397 FETCH (UID 181209 INTERNALDATE "06-Mar-2024 17:34:09 +0100")
* 11720 FETCH (FLAGS (\Seen))
? OK Fetch completed (0.003 + 0.000 + 0.002 secs).

But the messages mentioned in the first post have these UID+dates in my case: UID 181017 INTERNALDATE "06-Mar-2024 09:51:44 +0100" and UID 181080 INTERNALDATE "06-Mar-2024 11:44:39 +0100"

Tested the whole INBOX with this script, there are more cases of internaldate problems:

#!/usr/bin/env python3
import imaplib
from imaplib import IMAP4_SSL
import sys

login = sys.argv[1]
password = sys.argv[2]
with IMAP4_SSL("testrun.org") as M:
    M.login(login, password)
    M.select("INBOX", readonly=True)
    status, resp = M.uid("FETCH", "1:*", "(INTERNALDATE)")
    prev_date = None
    for line in resp:
        timestruct = imaplib.Internaldate2tuple(line)
        if prev_date and prev_date > timestruct:
            print(line.decode("ascii"))
        prev_date = timestruct

Running the script on my testrun account I got this output:

25 (UID 128685 INTERNALDATE "06-Sep-2023 15:44:10 +0200")
1133 (UID 147272 INTERNALDATE "14-Nov-2023 14:08:14 +0100")
1230 (UID 173965 INTERNALDATE "10-Feb-2024 17:26:56 +0100")
1401 (UID 174137 INTERNALDATE "11-Feb-2024 11:41:43 +0100")
1726 (UID 174464 INTERNALDATE "12-Feb-2024 11:49:52 +0100")
2439 (UID 175178 INTERNALDATE "14-Feb-2024 10:39:21 +0100")
3320 (UID 176111 INTERNALDATE "18-Feb-2024 08:41:20 +0100")
4401 (UID 177197 INTERNALDATE "21-Feb-2024 15:19:42 +0100")
4820 (UID 177623 INTERNALDATE "23-Feb-2024 14:21:36 +0100")
5099 (UID 177903 INTERNALDATE "24-Feb-2024 17:34:24 +0100")
6924 (UID 179736 INTERNALDATE "02-Mar-2024 12:12:26 +0100")
7284 (UID 180096 INTERNALDATE "03-Mar-2024 17:43:56 +0100")
7368 (UID 180180 INTERNALDATE "04-Mar-2024 10:41:58 +0100")
7412 (UID 180224 INTERNALDATE "04-Mar-2024 13:21:30 +0100")
7438 (UID 180250 INTERNALDATE "04-Mar-2024 14:06:57 +0100")
8389 (UID 181201 INTERNALDATE "06-Mar-2024 10:42:05 +0100")
8939 (UID 181753 INTERNALDATE "08-Mar-2024 05:47:56 +0100")
9051 (UID 181865 INTERNALDATE "08-Mar-2024 08:16:34 +0100")
9064 (UID 181878 INTERNALDATE "08-Mar-2024 08:53:17 +0100")
9760 (UID 182596 INTERNALDATE "10-Mar-2024 07:46:36 +0100")
10359 (UID 183206 INTERNALDATE "11-Mar-2024 18:27:43 +0100")
11276 (UID 184125 INTERNALDATE "13-Mar-2024 21:06:17 +0100")

System seem to have been rebooted on Mar 5 and not Mar 6, so reboots do not explain clock jumps.

On my nine.testrun.org account there are zero problems of this kind.

link2xt commented 8 months ago

Relying on INTERNALDATE was introduced in #3789 for Gmail which shuffles UIDs when a batch of messages is moved from Inbox to DeltaChat. If INTERNALDATE is this unreliable, maybe we should only use it for Gmail?

Or we can avoid ordering by INTERNALDATE completely and instead download the messages in the order we have seen them the first time. The first time we see the message we remember its Message-ID in imap table, so the order Message-IDs appear in imap table is the order we should download the messages even if their UIDs get shuffled after moving to DeltaChat folder. I don't see how to make it work in multi-device case though, second device that only sees messages already moved to DeltaChat folder will have no way to decide whether to order by INTERNALDATE or by UID.

link2xt commented 8 months ago

We can also do nothing because it does not happen often and the bug is actually on the server side, it should ensure that the clock does not jump.

iequidoo commented 8 months ago

We can also do nothing because it does not happen often and the bug is actually on the server side, it should ensure that the clock does not jump.

I think first of all the reason of clock jumps should be found and anyway Mailcow could guarantee that INTERNALDATE is at least monotonically increasing. But there's still a question what to do if two messages have the same.

link2xt commented 8 months ago

But there's still a question what to do if two messages have the same.

We sort by UID in this case, there is no problem with UIDs. Even sorting only by UIDs work, it only does not work for Gmail.

I looked on the messages on testrun.org from the server:

root@managed:/opt/mailcow-dockerized# docker compose exec dovecot-mailcow doveadm -f flow fetch -u link2xt@testrun.org "mailbox date.received date.saved uid" "UID" "181198:181205"
mailbox=INBOX date.received=2024-03-06 17:05:25 date.saved=2024-03-06 17:17:15 uid=181198
mailbox=INBOX date.received=2024-03-06 17:09:09 date.saved=2024-03-06 17:14:30 uid=181199
mailbox=INBOX date.received=2024-03-06 17:10:16 date.saved=2024-03-06 17:14:30 uid=181200
mailbox=INBOX date.received=2024-03-06 10:42:05 date.saved=2024-03-06 17:12:05 uid=181201
mailbox=INBOX date.received=2024-03-06 13:57:32 date.saved=2024-03-06 17:19:59 uid=181202
mailbox=INBOX date.received=2024-03-06 17:26:43 date.saved=2024-03-06 18:21:17 uid=181203
mailbox=INBOX date.received=2024-03-06 17:27:01 date.saved=2024-03-06 18:21:17 uid=181204
mailbox=INBOX date.received=2024-03-06 17:28:27 date.saved=2024-03-06 18:21:17 uid=181205

Here date.saved is almost correct (not off by > 5 hours), but date.received (this is INTERNALDATE, it also corresponds to mtime in case of Maildir) is in the past and date.saved is not monotonically increasing.

Also messages with Received headers, maybe something can be figured out by looking at them (censored out some IPs and addresses with XXX):

root@managed:/opt/mailcow-dockerized# docker compose exec dovecot-mailcow doveadm fetch -u link2xt@testrun.org "mailbox date.received date.saved uid hdr.Received" UID 181198:181205
mailbox: INBOX
date.received: 2024-03-06 17:05:25
date.saved: 2024-03-06 17:17:15
uid: 181198
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id sNIbDEWU6GXucwUAW+4EIw
    (envelope-from <noreply@github.com>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 17:05:25 +0100
from out-20.smtp.github.com (out-20.smtp.github.com [192.30.252.203])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256)
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id B17CC46B18
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 17:05:24 +0100 (CET)
from github.com (hubbernetes-node-729f14d.va3-iad.github.net [10.48.220.79])
    by smtp.github.com (Postfix) with ESMTPA id C5E408C110D
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 08:05:23 -0800 (PST)

mailbox: INBOX
date.received: 2024-03-06 17:09:09
date.saved: 2024-03-06 17:14:30
uid: 181199
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id EM7BMiWV6GXucwUAW+4EIw
    (envelope-from <XXX@deltachat.de>); Wed, 06 Mar 2024 17:09:09 +0100
from dd46606.kasserver.com (dd46606.kasserver.com [85.13.163.218])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256)
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id 57F3646586;
    Wed,  6 Mar 2024 17:09:09 +0100 (CET)
from [127.0.0.1] (XXX [XXX])
    by dd46606.kasserver.com (Postfix) with ESMTPSA id 6AF3A2500A76;
    Wed,  6 Mar 2024 17:09:08 +0100 (CET)

mailbox: INBOX
date.received: 2024-03-06 17:10:16
date.saved: 2024-03-06 17:14:30
uid: 181200
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id QLl7A2iV6GXucwUAW+4EIw
    (envelope-from <XXX@merlinux.eu>); Wed, 06 Mar 2024 17:10:16 +0100
from merlinux.eu (merlinux.eu [95.217.159.152])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256)
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id DB38A46ADD;
    Wed,  6 Mar 2024 17:10:14 +0100 (CET)

mailbox: INBOX
date.received: 2024-03-06 10:42:05
date.saved: 2024-03-06 17:12:05
uid: 181201
hdr.received: from mailcow.testrun.org ([fd4d:6169:6c63:6f77::a])
    by 9139fd506e7e with LMTP
    id iDFkLW066GWm6QIAW+4EIw
    (envelope-from <XXX@merlinux.eu>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 10:42:05 +0100
from merlinux.eu (merlinux.eu [IPv6:2a01:4f9:c010:78bc::1])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits))
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id 436A846B4C
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 10:42:04 +0100 (CET)

mailbox: INBOX
date.received: 2024-03-06 13:57:32
date.saved: 2024-03-06 17:19:59
uid: 181202
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id KBX0Mjxo6GUZMAQAW+4EIw
    (envelope-from <noreply@github.com>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 13:57:32 +0100
from out-21.smtp.github.com (out-21.smtp.github.com [192.30.252.204])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256)
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id 660B047664
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 13:57:31 +0100 (CET)
from github.com (hubbernetes-node-b157052.ac4-iad.github.net [10.52.205.17])
    by smtp.github.com (Postfix) with ESMTPA id 646F270034D
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 04:57:30 -0800 (PST)

mailbox: INBOX
date.received: 2024-03-06 17:26:43
date.saved: 2024-03-06 18:21:17
uid: 181203
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id uHS6J0OZ6GWIhQUAW+4EIw
    (envelope-from <noreply@github.com>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 17:26:43 +0100
from out-18.smtp.github.com (out-18.smtp.github.com [192.30.252.201])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256)
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id CC92746BFD
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 17:26:42 +0100 (CET)
from github.com (hubbernetes-node-f7ec888.va3-iad.github.net [10.48.200.43])
    by smtp.github.com (Postfix) with ESMTPA id F1256E1182
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 08:26:41 -0800 (PST)

mailbox: INBOX
date.received: 2024-03-06 17:27:01
date.saved: 2024-03-06 18:21:17
uid: 181204
hdr.received: from mailcow.testrun.org ([172.22.1.253])
    by 9139fd506e7e with LMTP
    id 8Aw9JVWZ6GWIhQUAW+4EIw
    (envelope-from <noreply@github.com>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 17:27:01 +0100
from out-18.smtp.github.com (out-18.smtp.github.com [192.30.252.201])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits))
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id 2910F46F83
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 17:27:01 +0100 (CET)
from github.com (hubbernetes-node-037471f.va3-iad.github.net [10.48.222.60])
    by smtp.github.com (Postfix) with ESMTPA id 3B052E0839
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 08:27:00 -0800 (PST)

mailbox: INBOX
date.received: 2024-03-06 17:28:27
date.saved: 2024-03-06 18:21:17
uid: 181205
hdr.received: from mailcow.testrun.org ([fd4d:6169:6c63:6f77::a])
    by 9139fd506e7e with LMTP
    id SC0/KKuZ6GWIhQUAW+4EIw
    (envelope-from <noreply@github.com>)
    for <link2xt@testrun.org>; Wed, 06 Mar 2024 17:28:27 +0100
from out-24.smtp.github.com (out-24.smtp.github.com [192.30.252.207])
    (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
    key-exchange X25519 server-signature RSA-PSS (4096 bits))
    (No client certificate requested)
    by mailcow.testrun.org (Postcow) with ESMTPS id 2FD57407A8
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 17:28:26 +0100 (CET)
from github.com (hubbernetes-node-de26f92.ac4-iad.github.net [10.52.142.37])
    by smtp.github.com (Postfix) with ESMTPA id 4A327641155
    for <link2xt@testrun.org>; Wed,  6 Mar 2024 08:28:25 -0800 (PST)

Mail with UID=181201 was apparently indeed received at 10:42:04 +0100, but only saved to the mailbox at 17:12. Could be it somehow got stuck in LMTP delivery e.g. because of rspamd?

I considered using SAVEDATE when it is supported, but it seems to be also not monotonically increasing (I assume it corresponds to date.saved), 17:17 followed up by 17:14, then 17:12, then 17:19. Same results via IMAP:

8079 (UID 181198 INTERNALDATE "06-Mar-2024 17:05:25 +0100" SAVEDATE "06-Mar-2024 17:17:15 +0100")
8080 (UID 181199 INTERNALDATE "06-Mar-2024 17:09:09 +0100" SAVEDATE "06-Mar-2024 17:14:30 +0100")
8081 (UID 181200 INTERNALDATE "06-Mar-2024 17:10:16 +0100" SAVEDATE "06-Mar-2024 17:14:30 +0100")
8082 (UID 181201 INTERNALDATE "06-Mar-2024 10:42:05 +0100" SAVEDATE "06-Mar-2024 17:12:05 +0100")
8083 (UID 181202 INTERNALDATE "06-Mar-2024 13:57:32 +0100" SAVEDATE "06-Mar-2024 17:19:59 +0100")
8084 (UID 181203 INTERNALDATE "06-Mar-2024 17:26:43 +0100" SAVEDATE "06-Mar-2024 18:21:17 +0100")
8085 (UID 181204 INTERNALDATE "06-Mar-2024 17:27:01 +0100" SAVEDATE "06-Mar-2024 18:21:17 +0100")
8086 (UID 181205 INTERNALDATE "06-Mar-2024 17:28:27 +0100" SAVEDATE "06-Mar-2024 18:21:17 +0100")
link2xt commented 8 months ago

Sidenote: SAVEDATE in Dovecot Maildir implementation uses ctime and is worse than INTERNALDATE for our usage

This is reported to Dovecot mailing list: https://dovecot.org/mailman3/hyperkitty/list/dovecot@dovecot.org/thread/GP6G4VLLS4YKFQNHIHUKUUTEJBW6X7B2/

For root@nine.testrun.org INBOX which is a simple chatmail instance, almost plain dovecot without virtualization, the results wrt INTERNALDATE vs SAVEDATE are even more strange:

1 (UID 360 INTERNALDATE "05-Feb-2024 01:11:50 +0100" SAVEDATE "08-Feb-2024 19:09:03 +0100")
2 (UID 361 INTERNALDATE "05-Feb-2024 11:31:48 +0100" SAVEDATE "08-Feb-2024 19:09:08 +0100")
3 (UID 362 INTERNALDATE "06-Feb-2024 11:27:01 +0100" SAVEDATE "08-Feb-2024 19:09:08 +0100")
4 (UID 363 INTERNALDATE "07-Feb-2024 11:25:56 +0100" SAVEDATE "08-Feb-2024 19:09:08 +0100")
5 (UID 364 INTERNALDATE "08-Feb-2024 11:57:09 +0100" SAVEDATE "08-Feb-2024 19:09:42 +0100")
6 (UID 365 INTERNALDATE "09-Feb-2024 11:54:01 +0100" SAVEDATE "10-Feb-2024 13:29:54 +0100")
7 (UID 366 INTERNALDATE "10-Feb-2024 11:25:31 +0100" SAVEDATE "10-Feb-2024 13:29:54 +0100")
8 (UID 367 INTERNALDATE "11-Feb-2024 11:21:38 +0100" SAVEDATE "16-Feb-2024 12:25:40 +0100")
9 (UID 368 INTERNALDATE "11-Feb-2024 19:13:23 +0100" SAVEDATE "15-Feb-2024 19:16:25 +0100")
10 (UID 369 INTERNALDATE "12-Feb-2024 11:16:42 +0100" SAVEDATE "16-Feb-2024 12:25:40 +0100")
11 (UID 370 INTERNALDATE "13-Feb-2024 11:23:23 +0100" SAVEDATE "16-Feb-2024 12:25:40 +0100")
12 (UID 371 INTERNALDATE "14-Feb-2024 11:25:47 +0100" SAVEDATE "16-Feb-2024 12:25:40 +0100")
13 (UID 372 INTERNALDATE "15-Feb-2024 11:26:16 +0100" SAVEDATE "19-Feb-2024 13:11:26 +0100")
14 (UID 373 INTERNALDATE "15-Feb-2024 22:08:30 +0100" SAVEDATE "21-Feb-2024 13:39:14 +0100")
15 (UID 374 INTERNALDATE "16-Feb-2024 11:25:16 +0100" SAVEDATE "19-Feb-2024 13:11:26 +0100")
16 (UID 375 INTERNALDATE "17-Feb-2024 11:24:06 +0100" SAVEDATE "19-Feb-2024 13:11:26 +0100")
17 (UID 376 INTERNALDATE "18-Feb-2024 01:11:19 +0100" SAVEDATE "21-Feb-2024 13:39:15 +0100")
18 (UID 377 INTERNALDATE "18-Feb-2024 11:16:35 +0100" SAVEDATE "19-Feb-2024 13:11:26 +0100")
19 (UID 378 INTERNALDATE "19-Feb-2024 01:11:26 +0100" SAVEDATE "21-Feb-2024 13:39:15 +0100")
20 (UID 379 INTERNALDATE "19-Feb-2024 11:14:35 +0100" SAVEDATE "21-Feb-2024 13:38:16 +0100")
21 (UID 380 INTERNALDATE "19-Feb-2024 23:08:33 +0100" SAVEDATE "21-Feb-2024 13:39:14 +0100")
22 (UID 381 INTERNALDATE "20-Feb-2024 01:13:31 +0100" SAVEDATE "21-Feb-2024 13:39:15 +0100")
23 (UID 382 INTERNALDATE "20-Feb-2024 11:26:10 +0100" SAVEDATE "21-Feb-2024 13:38:16 +0100")
24 (UID 383 INTERNALDATE "21-Feb-2024 11:28:13 +0100" SAVEDATE "21-Feb-2024 13:38:16 +0100")

I expected that SAVEDATE should always be exactly the same as INTERNALDATE unless someone does APPEND or COPY over IMAP, but apparently it is not the case.

In case of maildir INTERNALDATE aka received date corresponds to file mtime and SAVEDATE aka saved date corresponds to ctime: https://github.com/dovecot/core/blob/93eb0663336b17f66a67324de43e64bf0bc796c1/src/lib-storage/index/maildir/maildir-mail.c#L152-L182. Here is an example for mail with UID 373:

root@nine /home/vmail/mail/nine.testrun.org/root@nine.testrun.org/cur # stat 1708031310.M769290P3712350.nine,S=7898,W=8002:2,Sa
  File: 1708031310.M769290P3712350.nine,S=7898,W=8002:2,Sa
  Size: 7898        Blocks: 16         IO Block: 4096   regular file
Device: 9,2 Inode: 7864351     Links: 1
Access: (0600/-rw-------)  Uid: (  999/   vmail)   Gid: (  996/   vmail)
Access: 2024-02-16 08:34:04.374097798 +0100
Modify: 2024-02-15 22:08:30.769813368 +0100
Change: 2024-02-21 13:39:14.878163244 +0100
 Birth: 2024-02-15 22:08:30.769813368 +0100

ctime which is retured by SAVEDATE is 21 Feb and is not useful, what I expected is a file btime (which is exactly the same as mtime indeed). Even chown vmail:vmail 1708031310.M769290P3712350.nine,S=7898,W=8002:2,Sa updated ctime to the current timestamp. I think Dovecot should use btime from statx and otherwise say that SAVEDATE is not available. We cannot use SAVEDATE as long as it is using ctime, this is worse than using mtime/INTERNALDATE.

iequidoo commented 8 months ago

I think Dovecot should use btime from statx and otherwise say that SAVEDATE is not available. We cannot use SAVEDATE as long as it is using ctime, this is worse than using mtime/INTERNALDATE.

But it looks like using INTERNALDATE (mtime) is not so bad. What can be the reasons of its change after a mail is received? And anyway using mtime is a server implementation detail.

The problem is that messages are delayed arbitrarily, so they are anyway received in the wrong order if a client is constantly online and has no chance to order them properly. Maybe if we see an out-of-order (delayed) message (this needs some heuristics however, maybe using In-Reply-To / References), we should just process it the same way as we do for messages manually downloaded later?

link2xt commented 8 months ago

The problem is that messages are delayed arbitrarily

In this particular case there was no such problem, messages were received in the correct order and have correct UID order. Constantly online client would have downloaded them in the right order.

Maybe if we see an out-of-order (delayed) message (this needs some heuristics however, maybe using In-Reply-To / References), we should just process it the same way as we do for messages manually downloaded later?

In this case editor message replaced with square bracket error would need reprocessing after receiving "late" Member added message. Processing old messages that previously failed validation is adding too much complexity and will create more bugs e.g. if such messages are themselves changing group membership. Currently Delta Chat always processes messages no more than once and I would rather not change it without

Topological sort based on Message-ID, In-Reply-To and References could have solved the problem here e.g. if we sort first topologically, then use (INTERNALDATE, UID) pair to resolve ties.

iequidoo commented 8 months ago

Processing old messages that previously failed validation is adding too much complexity and will create more bugs e.g. if such messages are themselves changing group membership. Currently Delta Chat always processes messages no more than once and I would rather not change it without

+1, no message reprocessing of course. Looks like there's nothing special to be done for out-of-order (delayed) messages. For messages downloaded later we only replace placeholder messages in the db.

Topological sort based on Message-ID, In-Reply-To and References could have solved the problem here e.g. if we sort first topologically, then use (INTERNALDATE, UID) pair to resolve ties.

If the subject problem will be fixed for Mailcow, it seems the topological sort can be helpful only for Gmail. It can also help in case of message delivery delays, but only if a client is not constantly online, but luckily fetches messages at the proper moments.