stalwartlabs / mail-server

Secure & Modern All-in-One Mail Server (IMAP, JMAP, POP3, SMTP)
https://stalw.art
5.19k stars 214 forks source link

[bug]: Pre-existing folders are replaced when using fileinto :create #725

Closed esclear closed 2 months ago

esclear commented 2 months ago

What happened?

I migrated my old mailserver (postfix + dovecot) to Stalwart and am currently on v0.9.2. For the migration, I transferred all of my emails and the folder structure using the imapsync tool. I set up a fresh Thunderbird profile and downloaded all messages and all were there.

Afterwards, I also set up my old sieve script, which moves messages into folders, based on the envelope-to address (and basing the folder name on the address :detail). fileinto uses the :create flag, as sometimes the folders need to be created ad-hoc.

I received some messages and noticed that Thunderbird was behaving strangely; the folders where they should end up disappeared from my mailbox. From some manual debugging (see below), it appears to me that existing folders are being replaced (and that the old messages are lost).

How can we reproduce the problem?

  1. Create the account foo@<your-domain> and within it the folder INBOX/Foo-Stuff/Bar and put messages in there using IMAP (e.g. using Thunderbird or imapsync). I put two messages in mine.
  2. Set up the following Sieve script for this mailbox:

    if envelope :user :is "to" "foo" {
    if envelope :detail :matches "to" "*"{
    set :upperfirst "target" "${1}";
    fileinto :create "INBOX/Foo-Stuff/${target}";
    stop;
    }
    
    fileinto "INBOX/Foo-Stuff";
    stop;
    }
  3. Verify the contents of INBOX/Foo-Stuff/Bar, e.g. using IMAP directly:
    
    g1 SELECT "INBOX/Foo-Stuff/Bar"
    * 2 EXISTS
    * FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)
    * 0 RECENT
    * OK [PERMANENTFLAGS (\\Deleted \\Seen \\Answered \\Flagged \\Draft \\*)] All allowed
    * OK [UIDVALIDITY 597248659] UIDs valid
    * OK [UIDNEXT 3] Next predicted UID
    * OK [MAILBOXID (iaaaaeu)] Unique Mailbox ID
    g1 OK [READ-WRITE] SELECT completed
    f1 fetch 1:3 (BODY[HEADER.FIELDS (Subject)])
    * 1 FETCH (BODY[HEADER.FIELDS (SUBJECT)] {26}
    Subject: Old message 1

)

) f1 OK FETCH completed

4. Send a mail to `foo+bar@<your-domain>`
5. Verify the contents of `INBOX/Foo-Stuff/Bar` again:

g2 SELECT "INBOX/Foo-Stuff/Bar"

) f2 OK FETCH completed

6. The old messages are gone

I see that that the Unique Mailbox ID seems to have changed — I suspect that this is related to the problem.

### Version

v0.9.x

### What database are you using?

RocksDB

### What blob storage are you using?

RocksDB

### Where is your directory located?

Internal

### What operating system are you using?

Linux

### Relevant log output

```shell
2024-08-29T21:58:19Z TRACE Raw IMAP input received (imap.raw-input) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, size = 46, contents = "g SELECT "INBOX/Foo-Stuff/Bar"\r\n"
2024-08-29T21:58:19Z TRACE Data store iteration operation (store.data-iterate) elapsed = 1ms
2024-08-29T21:58:19Z TRACE Data store iteration operation (store.data-iterate) elapsed = 1ms
2024-08-29T21:58:19Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:19Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:19Z DEBUG IMAP SELECT command (imap.select) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, mailboxName = "INBOX/Foo-Stuff/Bar", accountId = 2, mailboxId = 148, total = 2, uidNext = 3, uidValidity = 597248659, elapsed = 6ms
2024-08-29T21:58:19Z TRACE Raw IMAP output sent (imap.raw-output) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, size = 317, contents = "* 2 EXISTS\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* 0 RECENT\r\n* OK [PERMANENTFLAGS (\\Deleted \\Seen \\Answered \\Flagged \\Draft \\*)] All allowed\r\n* OK [UIDVALIDITY 597248659] UIDs valid\r\n* OK [UIDNEXT 3] Next predicted UID\r\n* OK [MAILBOXID (iaaaaeu)] Unique Mailbox ID\r\ng OK [READ-WRITE] SELECT completed\r\n"
2024-08-29T21:58:21Z INFO Dropped connection from blocked IP address (network.drop-blocked) listenerId = "submissions", localPort = 465, remoteIp = 194.169.175.65, remotePort = 55110
2024-08-29T21:58:31Z INFO SMTP connection started (smtp.connection-start) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.transfer-limit", result = "Integer(262144000)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.duration", result = "Integer(600000)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.timeout", result = "Integer(300000)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.spf.verify.ehlo", result = "Integer(2)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.spf.verify.mail-from", result = "Integer(2)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.iprev.verify", result = "Integer(2)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.ehlo.require", result = "Integer(1)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.ehlo.reject-non-fqdn", result = "Integer(1)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.directory", result = "Integer(0)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.directory", result =
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.require", result = "Integer(0)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.errors.total", result = "Integer(3)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.errors.wait", result = "Integer(5000)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.must-match-sender", result = "Integer(1)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.expn", result = "Integer(0)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.vrfy", result = "Integer(0)"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.connect.script", result =
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "server.connect.hostname", result = "String("mail.receiver.com")"
2024-08-29T21:58:31Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.connect.greeting", result = "String("mail.receiver.com Stalwart ESMTP at your service")"
2024-08-29T21:58:31Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 54, contents = "220 mail.receiver.com Stalwart ESMTP at your service\r\n"
2024-08-29T21:58:31Z TRACE Raw SMTP input received (smtp.raw-input) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 29, contents = "EHLO mout-p-201.mailbox.org\r\n"
2024-08-29T21:58:31Z INFO SMTP EHLO command (smtp.ehlo) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, domain = "mout-p-201.mailbox.org"
2024-08-29T21:58:32Z INFO SPF EHLO check failed (smtp.spf-ehlo-fail) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, domain = "mout-p-201.mailbox.org", result = No SPF record (spf.none), elapsed = 527ms
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "report.spf.send", result = "Array([Integer(1), Integer(86400000)])"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.ehlo.script", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.pipelining", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.chunking", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.expn", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.vrfy", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.requiretls", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.dsn", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.mechanisms", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.future-release", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.future-release", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.deliver-by", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.deliver-by", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.mt-priority", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.mt-priority", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.size", result = "Integer(104857600)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.no-soliciting", result = "String("")"
2024-08-29T21:58:32Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 210, contents = "250-mail.receiver.com you had me at EHLO\r\n250-STARTTLS\r\n250-SMTPUTF8\r\n250-SIZE 104857600\r\n250-REQUIRETLS\r\n250-PIPELINING\r\n250-NO-SOLICITING\r\n250-ENHANCEDSTATUSCODES\r\n250-CHUNKING\r\n250-BINARYMIME\r\n250 8BITMIME\r\n"
2024-08-29T21:58:32Z TRACE Raw SMTP input received (smtp.raw-input) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 10, contents = "STARTTLS\r\n"
2024-08-29T21:58:32Z DEBUG SMTP STARTTLS command (smtp.start-tls) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286
2024-08-29T21:58:32Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 31, contents = "220 2.0.0 Ready to start TLS.\r\n"
2024-08-29T21:58:32Z INFO TLS handshake (tls.handshake) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, listenerId = "smtp", version = "TLSv1_3", details = "TLS13_AES_256_GCM_SHA384"
2024-08-29T21:58:32Z TRACE Raw SMTP input received (smtp.raw-input) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 29, contents = "EHLO mout-p-201.mailbox.org\r\n"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.pipelining", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.chunking", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.expn", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.vrfy", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.requiretls", result = "Integer(1)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.dsn", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.auth.mechanisms", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.future-release", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.future-release", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.deliver-by", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.deliver-by", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.mt-priority", result = "Integer(0)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.mt-priority", result =
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.size", result = "Integer(104857600)"
2024-08-29T21:58:32Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.no-soliciting", result = "String("")"
2024-08-29T21:58:32Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 196, contents = "250-mail.receiver.com you had me at EHLO\r\n250-SMTPUTF8\r\n250-SIZE 104857600\r\n250-REQUIRETLS\r\n250-PIPELINING\r\n250-NO-SOLICITING\r\n250-ENHANCEDSTATUSCODES\r\n250-CHUNKING\r\n250-BINARYMIME\r\n250 8BITMIME\r\n"
2024-08-29T21:58:32Z TRACE Raw SMTP input received (smtp.raw-input) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 105, contents = "MAIL FROM:<sender@sender.com> SIZE=812 BODY=8BITMIME\r\nRCPT TO:<foo+bar@receiver.com>\r\nDATA\r\n"
2024-08-29T21:58:33Z INFO IPREV check passed (smtp.iprev-pass) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, domain = "mout-p-201.mailbox.org", result = IPREV check passed (iprev.pass) { details = ["mout-p-201.mailbox.org."] }, elapsed = 1576ms
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.mail.script", result =
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.mail.rewrite", result =
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.size", result = "Integer(104857600)"
2024-08-29T21:58:33Z INFO SPF From check passed (smtp.spf-from-pass) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, domain = "mout-p-201.mailbox.org", from = "sender@sender.com", result = SPF check passed (spf.pass), elapsed = 65ms
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "report.spf.send", result = "Array([Integer(1), Integer(86400000)])"
2024-08-29T21:58:33Z INFO SMTP MAIL FROM command (smtp.mail-from) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, from = "sender@sender.com"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.rcpt.errors.total", result = "Integer(5)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.rcpt.errors.wait", result = "Integer(5000)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.rcpt.max-recipients", result = "Integer(100)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.extensions.dsn", result = "Integer(0)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.size", result = "Integer(104857600)"
2024-08-29T21:58:33Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 14, contents = "250 2.1.0 OK\r\n"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.rcpt.script", result =
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.rcpt.directory", result = "String("*")"
2024-08-29T21:58:33Z TRACE Write batch operation (store.data-write) elapsed = 4ms, total = 2
2024-08-29T21:58:33Z INFO SMTP RCPT TO command (smtp.rcpt-to) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, to = "foo+bar@receiver.com"
2024-08-29T21:58:33Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 14, contents = "250 2.1.5 OK\r\n"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.messages", result = "Integer(10)"
2024-08-29T21:58:33Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 46, contents = "354 Start mail input; end with <CRLF>.<CRLF>\r\n"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.limits.received-headers", result = "Integer(50)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.dkim.verify", result = "Integer(2)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.dmarc.verify", result = "Integer(2)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "report.dkim.send", result = "Array([Integer(1), Integer(86400000)])"
2024-08-29T21:58:33Z INFO DKIM verification passed (smtp.dkim-pass) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, strict = false, result = [DKIM verification passed (dkim.pass) { domain = "sender.com" }], elapsed = 7ms
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.arc.verify", result = "Integer(2)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.arc.seal", result = "String("rsa-sender.com")"
2024-08-29T21:58:33Z INFO ARC verification passed (smtp.arc-pass) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, strict = false, result = No DKIM signature (dkim.none), elapsed = 0ms
2024-08-29T21:58:33Z INFO DMARC check passed (smtp.dmarc-pass) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, strict = false, domain = "sender.com", policy = "quarantine", result = DMARC check passed (dmarc.pass), elapsed = 25ms
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "report.dmarc.send", result = "Array([Integer(1), Integer(86400000)])"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "report.dmarc.aggregate.send", result = "Integer(3)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.add-headers.received", result = "Integer(1)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.add-headers.auth-results", result = "Integer(1)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.add-headers.received-spf", result = "Integer(1)"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.script", result = "String("spam-filter")"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "sieve.trusted.from-addr", result = "String("MAILER-DAEMON@sender.com")"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "sieve.trusted.from-name", result = "String("Automated Message")"
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "sieve.trusted.return-path", result =
2024-08-29T21:58:33Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "sieve.trusted.sign", result = "Array([String("rsa-sender.com"), String("ed25519-sender.com")])"
2024-08-29T21:58:33Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:33Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:33Z WARN Sieve runtime error (sieve.runtime-error) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "spam-trap", details = Unknown store, details = Sieve runtime error
2024-08-29T21:58:33Z DEBUG Not enough training data for spam filter (spam.not-enough-training-data) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, details = [1, 3, 200]
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:41Z DEBUG Sieve action: Accept (sieve.action-accept) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, details = ["AddHeader { name: "X-Spam-Status", value: "No, score=0.9083890177858087" }", "AddHeader { name: "X-Spam-Result", value: "SPF_ALLOW (-0.2),\\r\\n\\tFROM_HAS_DN (0),\\r\\n\\tARC_NA (0),\\r\\n\\tRCVD_COUNT_ONE (0),\\r\\n\\tRCVD_IN_DNSWL_LOW (-0.1),\\r\\n\\tDKIM_ALLOW (-0.2),\\r\\n\\tSINGLE_SHORT_PART (0),\\r\\n\\tFROM_EQ_ENVFROM (0),\\r\\n\\tDKIM_SIGNED (0),\\r\\n\\tPREVIOUSLY_DELIVERED (0),\\r\\n\\tURIBL_BLOCKED (0),\\r\\n\\tRCVD_TLS_ALL (0),\\r\\n\\tRCPT_COUNT_ONE (0),\\r\\n\\tTO_MATCH_ENVRCPT_ALL (0),\\r\\n\\tDMARC_POLICY_ALLOW (-0.5),\\r\\n\\tMID_RHS_MATCH_FROM (1),\\r\\n\\tTAGGED_RCPT (0),\\r\\n\\tTO_DN_NONE (0)" }"]
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "queue.schedule.notify", result = "Array([Integer(86400000), Integer(259200000)])"
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "queue.schedule.expire", result = "Integer(432000000)"
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "session.data.add-headers.return-path", result = "Integer(1)"
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.dkim.sign", result = "Integer(0)"
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, id = "auth.dkim.sign", result =
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:41Z TRACE Blob write operation (store.blob-write) key = base64:MEq9H/lC6FcbQdCXGTwdaQQV65m6Sih1q5EW/JCXOcA=, elapsed = 0ms, size = 2878
2024-08-29T21:58:41Z INFO Queued message for delivery (queue.queue-message) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, nextRetry = 2024-08-29T21:58:41Z, nextDsn = 2024-08-30T21:58:41Z, expires = 2024-09-03T21:58:41Z
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 5
2024-08-29T21:58:41Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 40, contents = "250 2.0.0 Message queued for delivery.\r\n"
2024-08-29T21:58:41Z DEBUG SMTP QUIT command (smtp.quit) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286
2024-08-29T21:58:41Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, size = 16, contents = "221 2.0.0 Bye.\r\n"
2024-08-29T21:58:41Z INFO SMTP connection ended (smtp.connection-end) listenerId = "smtp", localPort = 25, remoteIp = 2001:67c:2050:0:465::201, remotePort = 45286, elapsed = 9501ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 2
2024-08-29T21:58:41Z INFO Delivery attempt started (delivery.attempt-start) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1
2024-08-29T21:58:41Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, domain = "receiver.com", total = 0
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, id = "queue.outbound.next-hop", result = "String("local")"
2024-08-29T21:58:41Z TRACE Blob read operation (store.blob-read) key = base64:MEq9H/lC6FcbQdCXGTwdaQQV65m6Sih1q5EW/JCXOcA=, elapsed = 0ms, size = 2878
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 32ms
2024-08-29T21:58:41Z TRACE Blob read operation (store.blob-read) key = base64:IwTJ/3YQGBp7uWoghygeasFOUQGi/7rdTeEGFXE8PuY=, elapsed = 0ms, size = 2868
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 2
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 7
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 8
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 5
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 7ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 25ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 2
2024-08-29T21:58:41Z TRACE Blob write operation (store.blob-write) key = base64:Jk7kqR+NzRvPnqB8HWUfjPwAwpc0hUecV0BQBfB9bv4=, elapsed = 0ms, size = 2894
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 4
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 28ms, total = 30
2024-08-29T21:58:41Z INFO Message ingested (message-ingest.ham) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, accountId = 2, documentId = 5820, mailboxId = [125], blobId = "264ee4a91f8dcd1bcf9ea07c1d651f8cfc00c2973485479c57405005f07d6efe", changeId = 194382337167171585, size = 4499, elapsed = 79ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Expression evaluation result (eval.result) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, id = "queue.schedule.retry", result = "Array([Integer(120000), Integer(300000), Integer(600000), Integer(900000), Integer(1800000), Integer(3600000), Integer(7200000)])"
2024-08-29T21:58:41Z INFO DSN success notification (delivery.dsn-success) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, to = "foo+bar@receiver.com", hostname = "localhost", code = 250, details = "OK"
2024-08-29T21:58:41Z INFO Delivery completed (delivery.completed) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, elapsed = 0ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 5
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 3
2024-08-29T21:58:41Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 194382321895542784, from = "sender@sender.com", to = ["foo+bar@receiver.com"], size = 4445, total = 1, elapsed = 123ms
2024-08-29T21:58:41Z TRACE Blob read operation (store.blob-read) key = base64:Jk7kqR+NzRvPnqB8HWUfjPwAwpc0hUecV0BQBfB9bv4=, elapsed = 0ms, size = 2894
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 30
2024-08-29T21:58:41Z INFO Full-text search index done (fts-index.index) accountId = 2, collection = email, documentId = 5820, elapsed = 1ms
2024-08-29T21:58:41Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 4
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:41Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:42Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:42Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:42Z TRACE Data store iteration operation (store.data-iterate) elapsed = 2ms
2024-08-29T21:58:42Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Raw IMAP input received (imap.raw-input) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, size = 47, contents = "g2 SELECT "INBOX/Foo-Stuff/Bar"\r\n"
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z TRACE Data store iteration operation (store.data-iterate) elapsed = 0ms
2024-08-29T21:58:49Z DEBUG IMAP SELECT command (imap.select) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, mailboxName = "INBOX/Foo-Stuff/Bar", accountId = 2, mailboxId = 125, total = 1, uidNext = 2, uidValidity = 761914443, elapsed = 2ms
2024-08-29T21:58:49Z TRACE Raw IMAP output sent (imap.raw-output) listenerId = "imaptls", localPort = 993, remoteIp = 2001:0000:0000:1234:5678:9abcd:1234:5678, remotePort = 35140, size = 357, contents = "* OK [CLOSED] Closed previous mailbox\r\n* 1 EXISTS\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* 0 RECENT\r\n* OK [PERMANENTFLAGS (\\Deleted \\Seen \\Answered \\Flagged \\Draft \\*)] All allowed\r\n* OK [UIDVALIDITY 761914443] UIDs valid\r\n* OK [UIDNEXT 2] Next predicted UID\r\n* OK [MAILBOXID (iaaaad0)] Unique Mailbox ID\r\ng2 OK [READ-WRITE] SELECT completed\r\n"

Code of Conduct

mdecimus commented 2 months ago

The fileinto command is case sensitive, you probably created another INBOX folder at the root level.

esclear commented 2 months ago

I don't see one. Wouldn't there need to be a mention of INBOX in a different casing then? In the IMAP session, I used identical casings in both selects/fetches, so I'm not sure how capitalization would play into this?

mdecimus commented 2 months ago

To confirm this you can try exporting your account and check the JSON file containing the mailbox structure.

esclear commented 2 months ago

Thanks! Indeed, there is also an Inbox mailbox in the mailbox.json file. I suspect that this is the default one generated by Stalwart.

Still, I did not expect this to make a difference, since RFC 3501 stipulates that the INBOX mailbox name is case-insensitive — and, even if it appears as part of a path, I'd expect the INBOX part to be treated case-insensitively.

But apart from that, in this situation, the Sieve script, my MUA, and the IMAP session all referenced the path in INBOX. So I'm not sure how the existence of Inbox would lead to the (re)creation of a folder in INBOX?

esclear commented 2 months ago

Okay, thinking a bit further about this, I have a suspicion:

However, INBOX doesn't seem to always take precedence, since the folders under Inbox, which don't exist under INBOX are still found, including their contents. 🤔 Would Stalwart (looking for INBOX/Foo in IMAP) use Inbox/Foo, if INBOX exists, but INBOX/Foo doesn't?

Yeah, so this is unexpected. 😅

Personally, I'd treat the INBOX part as case-insensitive in Sieve as well. Sec 4.1 of RFC 5228 doesn't say that it has to be treated case-sensitive (although quoted strings are case-sensitive). In my opinion, doing this mapping would be sensible, as it'd have saved me from this problem and likely others as well. From my interpretation of the fileinto action, that would also be permitted by the standard (either as part of the "delivery to an implementation-defined mailbox", or in the same vein as the reencoding).

I am not sure, how other servers handle this. What do you think?

mdecimus commented 2 months ago

I've just changed the way folders are searched so Inbox is case insensitive.