[bug]: Slow message receipt #1090

bb4242 · 2025-01-14T18:58:25Z

bb4242
Jan 14, 2025

What happened?

Hello! 👋 For the last day or two, incoming messages have been taking longer than usual (about 90 seconds) to be received by Stalwart. Checking timing in the logs, the bulk of the time spent seems to be related to the spam filter (see logs below).

Previously, message reception was very fast. I'm not exactly sure what's changed in the last few days - I haven't upgraded Stalwart for several weeks. Do you have any idea what might be causing this behavior? Thanks!

How can we reproduce the problem?

Send an email to Stalwart.
Observe that the connection takes about 90 seconds to complete.

Version

v0.10.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

Jan 14 12:33:54 mail stalwart-mail[1095]: 2025-01-14T18:33:54Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, id = "sieve.trusted.sign", result = "Array([String("rsa-"), String("ed25519-")])"
Jan 14 12:34:09 mail stalwart-mail[1095]: 2025-01-14T18:34:09Z DEBUG Sieve runtime error (sieve.runtime-error) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, id = "spam-trap", details = Unknown store, details = Sieve runtime error
Jan 14 12:34:09 mail stalwart-mail[1095]: 2025-01-14T18:34:09Z DEBUG Not enough training data for spam filter (spam.not-enough-training-data) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, details = [12, 9, 200]
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z TRACE Write batch operation (store.data-write) elapsed = 0ms, total = 1
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z DEBUG Balancing spam filter training data (spam.train-balance) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, details = [true, 0.9, 12, 9], result = false
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z DEBUG Sieve action: Accept (sieve.action-accept) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, id = "spam-filter", elapsed = 73300ms
Jan 14 12:35:08 mail stalwart-mail[1095]: 2025-01-14T18:35:08Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = X.X.X.X, remotePort = 57730, id = "queue.schedule.notify", result = "Array([Integer(86400000), Integer(259200000)])"

Code of Conduct

I agree to follow this project's Code of Conduct

mdecimus · 2025-01-14T20:48:25Z

mdecimus
Jan 14, 2025
Maintainer

Hi, I suggest that you upgrade to version 0.11.x, in particular it includes performance improvements to the spam filter. It will also provide more useful debugging information to help you detect the issue (it's probably DNS timeouts). Make sure you read the UPGRADING file before upgrading.

1 reply

bb4242 Jan 14, 2025
Author

Thanks @mdecimus. I'll explore upgrading (it may take a little bit as I'm on NixOS 24.11 and 0.11.x isn't released there yet). And in the meantime, the pointer to check for possible DNS timeouts is helpful. Will post back here what I find.

Have a nice day!

bb4242 · 2025-01-14T22:33:51Z

bb4242
Jan 14, 2025
Author

Did a bit more digging.

First, I can't find any indication that DNS queries are slow on the server. I had been using an ad-blocking upstream DNS server, and thought perhaps a poorly configured blocklist was causing problems, but the problem of slow delivery remains after switching to a non-adblocking upstream server (1.1.1.1).

Second, I'm now sometimes receiving multiple copies of emails that are sent from other providers. I suspect the sending SMTP server seems to think something has gone wrong in the delivery process and needs to retry sending the message multiple times. In these logs, the sender (protonmail) delivers the same message 3 times over the course of a few minutes:

Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO Delivery attempt started (delivery.attempt-start) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1, domain = "ZZZ", total = 0
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO Message ingested (message-ingest.ham) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1, accountId = 65, documentId = 101, mailboxId = [0], blobId = "33c8a0a1a70146f6dcf62d9bb00ed65a86bbda4acba8d4c217317eaf9a9e54da", changeId = 219387784039759945, messageId = "", size = 4111, elapsed = 0ms
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO Full-text search index done (fts-index.index) accountId = 65, collection = email, documentId = 101, elapsed = 1ms
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO DSN success notification (delivery.dsn-success) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1, to = "YYY@ZZZ", hostname = "localhost", code = 250, details = "OK"
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO Delivery completed (delivery.completed) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1, elapsed = 0ms
Jan 14 16:04:07 mail stalwart-mail[1096]: 2025-01-14T22:04:07Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 219387588383866902, from = "[email protected]", to = ["YYY@ZZZ"], size = 4111, total = 1, elapsed = 4ms
Jan 14 16:08:46 mail stalwart-mail[1096]: 2025-01-14T22:08:46Z INFO Invalid EHLO command (smtp.invalid-ehlo) listenerId = "smtp", localPort = 25, remoteIp = 62.60.190.160, remotePort = 60774, domain = "User"
Jan 14 16:08:46 mail stalwart-mail[1096]: 2025-01-14T22:08:46Z INFO Authentication not allowed (smtp.auth-not-allowed) listenerId = "smtp", localPort = 25, remoteIp = 62.60.190.160, remotePort = 60774
Jan 14 16:10:42 mail stalwart-mail[1096]: 2025-01-14T22:10:42Z INFO SMTP EHLO command (smtp.ehlo) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, domain = "mail-4319.protonmail.ch"
Jan 14 16:10:42 mail stalwart-mail[1096]: 2025-01-14T22:10:42Z INFO SPF EHLO check passed (smtp.spf-ehlo-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, domain = "mail-4319.protonmail.ch", result = SPF check passed (spf.pass), elapsed = 122ms
Jan 14 16:10:42 mail stalwart-mail[1096]: 2025-01-14T22:10:42Z INFO TLS handshake (tls.handshake) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, listenerId = "smtp", version = "TLSv1_3", details = "TLS13_AES_256_GCM_SHA384"
Jan 14 16:10:43 mail stalwart-mail[1096]: 2025-01-14T22:10:43Z INFO IPREV check passed (smtp.iprev-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, domain = "mail-4319.protonmail.ch", result = IPREV check passed (iprev.pass) { details = ["mail-4319.protonmail.ch."] }, elapsed = 259ms
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z INFO SPF From check passed (smtp.spf-from-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, domain = "mail-4319.protonmail.ch", from = "[email protected]", result = SPF check passed (spf.pass), elapsed = 5262ms
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z INFO SMTP MAIL FROM command (smtp.mail-from) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, from = "[email protected]"
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z INFO SMTP RCPT TO command (smtp.rcpt-to) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, to = "YYY@ZZZ"
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z INFO DKIM verification passed (smtp.dkim-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, strict = false, result = [DKIM verification passed (dkim.pass) { domain = "protonmail.com" }], elapsed = 30ms
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z WARN ARC sealer not found (arc.sealer-not-found) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, id = "rsa-"
Jan 14 16:10:48 mail stalwart-mail[1096]: 2025-01-14T22:10:48Z INFO ARC verification passed (smtp.arc-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, strict = false, result = No DKIM signature (dkim.none), elapsed = 0ms
Jan 14 16:10:49 mail stalwart-mail[1096]: 2025-01-14T22:10:49Z INFO DMARC check passed (smtp.dmarc-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, strict = false, domain = "protonmail.com", policy = "quarantine", result = DMARC check passed (dmarc.pass), elapsed = 132ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO SMTP EHLO command (smtp.ehlo) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, domain = "mail-4319.protonmail.ch"
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO SPF EHLO check passed (smtp.spf-ehlo-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, domain = "mail-4319.protonmail.ch", result = SPF check passed (spf.pass), elapsed = 0ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO IPREV check passed (smtp.iprev-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, domain = "mail-4319.protonmail.ch", result = IPREV check passed (iprev.pass) { details = ["mail-4319.protonmail.ch."] }, elapsed = 0ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO SPF From check passed (smtp.spf-from-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, domain = "mail-4319.protonmail.ch", from = "[email protected]", result = SPF check passed (spf.pass), elapsed = 0ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO SMTP MAIL FROM command (smtp.mail-from) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, from = "[email protected]"
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO SMTP RCPT TO command (smtp.rcpt-to) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, to = "YYY@ZZZ"
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO DKIM verification passed (smtp.dkim-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, strict = false, result = [DKIM verification passed (dkim.pass) { domain = "protonmail.com" }], elapsed = 0ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z WARN ARC sealer not found (arc.sealer-not-found) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, id = "rsa-"
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO ARC verification passed (smtp.arc-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, strict = false, result = No DKIM signature (dkim.none), elapsed = 0ms
Jan 14 16:11:39 mail stalwart-mail[1096]: 2025-01-14T22:11:39Z INFO DMARC check passed (smtp.dmarc-pass) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, strict = false, domain = "protonmail.com", policy = "quarantine", result = DMARC check passed (dmarc.pass), elapsed = 0ms
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Queued message for delivery (queue.queue-message) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 13829, queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, nextRetry = 2025-01-14T22:12:17Z, nextDsn = 2025-01-15T22:12:17Z, expires = 2025-01-19T22:12:17Z
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Delivery attempt started (delivery.attempt-start) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1, domain = "ZZZ", total = 0
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Message ingested (message-ingest.ham) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1, accountId = 65, documentId = 133, mailboxId = [0], blobId = "fa9ded903f5eb252482168db2d998cc845e671fae6308dfe8dcd1c8c7c36a08d", changeId = 219388812235636811, messageId = "", size = 4105, elapsed = 0ms
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Full-text search index done (fts-index.index) accountId = 65, collection = email, documentId = 133, elapsed = 0ms
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO DSN success notification (delivery.dsn-success) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1, to = "YYY@ZZZ", hostname = "localhost", code = 250, details = "OK"
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Delivery completed (delivery.completed) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1, elapsed = 0ms
Jan 14 16:12:17 mail stalwart-mail[1096]: 2025-01-14T22:12:17Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 219388626111299607, from = "[email protected]", to = ["YYY@ZZZ"], size = 4105, total = 1, elapsed = 2ms
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Queued message for delivery (queue.queue-message) listenerId = "smtp", localPort = 25, remoteIp = 185.70.43.19, remotePort = 31333, queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, nextRetry = 2025-01-14T22:13:07Z, nextDsn = 2025-01-15T22:13:07Z, expires = 2025-01-19T22:13:07Z
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Delivery attempt started (delivery.attempt-start) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1, domain = "ZZZ", total = 0
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Message ingested (message-ingest.ham) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1, accountId = 65, documentId = 130, mailboxId = [0], blobId = "14efb373e000621f41fe484f0c16e44d2b0892d07002b8ab9d944387d6346657", changeId = 219388915801391181, messageId = "", size = 4050, elapsed = 1ms
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Full-text search index done (fts-index.index) accountId = 65, collection = email, documentId = 130, elapsed = 1ms
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO DSN success notification (delivery.dsn-success) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1, to = "YYY@ZZZ", hostname = "localhost", code = 250, details = "OK"
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Delivery completed (delivery.completed) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1, elapsed = 0ms
Jan 14 16:13:07 mail stalwart-mail[1096]: 2025-01-14T22:13:07Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 219388731790983192, from = "[email protected]", to = ["YYY@ZZZ"], size = 4050, total = 1, elapsed = 4ms

Very strange. 😛 I have no idea if this is related to the slow delivery problem, but it seems suspicious that both problems started about the same time. Any ideas?

3 replies

mdecimus Jan 15, 2025
Maintainer

I recommend that you upgrade to 0.11 whenever you have a chance. The performance enhancements to the spam filter are briefly discussed in the blog announcement.
It will also provide more information in the logs to help you track down the cause of the delay.

bb4242 Jan 16, 2025
Author

Sounds good. I tried a bit with upgrading to 0.11 myself prior to it being released in nixpkgs today (the current PR is here) but ran into some trouble getting it to compile. I may just wait until that PR merges.

In the meantime, I got an email from my protonmail account (sent from the protonmail mailer daemon) that I was using to test sending emails to my stalwart server. The email said:

<[email protected]>: lost connection with mail.XXX.com[X.X.X.X] while
    sending end of data -- message may be sent more than once

So I guess that's a clue why I've been receiving many copies of the same emails.

mdecimus Jan 17, 2025
Maintainer

I'm not familiar with Nix, but is a PR needed for each new version that is released? If so please update it to version 0.11.2 that was just released.

bb4242 · 2025-01-17T17:43:48Z

bb4242
Jan 17, 2025
Author

Yes, PRs into the nixpkgs repository are how new versions of software are released in nix. Hopefully we can get 0.11.2 merged in shortly. :)

…

On Friday, January 17th, 2025 at 11:39 AM, Mauro D. ***@***.***> wrote: I'm not familiar with Nix, but is a PR needed for each new version that is released? If so please update it to version 0.11.2 that was just released. — Reply to this email directly, [view it on GitHub](#1090 (reply in thread)), or [unsubscribe](https://github.com/notifications/unsubscribe-auth/ACM2CSAHYZQHOTO5UKKZMH32LE54JAVCNFSM6AAAAABVFX4SG2VHI2DSMVQWIX3LMV43URDJONRXK43TNFXW4Q3PNVWWK3TUHMYTCOBWHE4DKMI). You are receiving this because you authored the thread.Message ID: ***@***.***>

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug]: Slow message receipt #1090

{{title}}

Replies: 3 comments 4 replies

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

[bug]: Slow message receipt #1090

bb4242 Jan 14, 2025

What happened?

How can we reproduce the problem?

Version

What database are you using?

What blob storage are you using?

Where is your directory located?

What operating system are you using?

Relevant log output

Code of Conduct

Replies: 3 comments · 4 replies

mdecimus Jan 14, 2025 Maintainer

bb4242 Jan 14, 2025 Author

bb4242 Jan 14, 2025 Author

mdecimus Jan 15, 2025 Maintainer

bb4242 Jan 16, 2025 Author

mdecimus Jan 17, 2025 Maintainer

bb4242 Jan 17, 2025 Author

bb4242
Jan 14, 2025

Replies: 3 comments 4 replies

mdecimus
Jan 14, 2025
Maintainer

bb4242 Jan 14, 2025
Author

bb4242
Jan 14, 2025
Author

mdecimus Jan 15, 2025
Maintainer

bb4242 Jan 16, 2025
Author

mdecimus Jan 17, 2025
Maintainer

bb4242
Jan 17, 2025
Author