[bug]: Delivery Slow

[ideazh]

What happened?

Expected Delivery completion time is optimized from 132000ms to within 5000ms

How can we reproduce the problem?

Send an email to 126.com mailbox.

Version

v0.10.x

What database are you using?

None

What blob storage are you using?

None

Where is your directory located?

None

What operating system are you using?

None

Relevant log output

2024-11-10T08:38:46Z INFO ...
2024-11-10T08:40:56Z WARN No TLS certificates available (tls.no-certificates-available) total = 0
2024-11-10T08:40:57Z INFO SMTP EHLO command (smtp.ehlo) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, domain = "name-pc"
2024-11-10T08:40:57Z INFO Authentication successful (auth.success) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, accountName = "contact", accountId = 6
2024-11-10T08:40:57Z INFO SMTP MAIL FROM command (smtp.mail-from) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, from = "[email protected]"
2024-11-10T08:40:57Z INFO SMTP RCPT TO command (smtp.rcpt-to) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, to = "[email protected]"
2024-11-10T08:40:58Z INFO DKIM verification failed (smtp.dkim-fail) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, strict = false, result = [], elapsed = 0ms
2024-11-10T08:40:58Z WARN ARC sealer not found (arc.sealer-not-found) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, id = "rsa-"
2024-11-10T08:40:58Z INFO ARC verification passed (smtp.arc-pass) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, strict = false, result = No DKIM signature (dkim.none), elapsed = 0ms
2024-11-10T08:40:58Z INFO Queued message submission for delivery (queue.queue-message-authenticated) listenerId = "submissions", localPort = 465, remoteIp = 172.17.0.1, remotePort = 46814, queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, nextRetry = 2024-11-10T08:40:58Z, nextDsn = 2024-11-11T08:40:58Z, expires = 2024-11-15T08:40:58Z
2024-11-10T08:40:58Z INFO Delivery attempt started (delivery.attempt-start) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1
2024-11-10T08:40:58Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", total = 0
2024-11-10T08:40:59Z INFO Error fetching TLS-RPT record (tls-rpt.record-fetch-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", causedBy = DNS record not found (mail-auth.dns-record-not-found) { code = No Error }, elapsed = 505ms
2024-11-10T08:40:59Z INFO MTA-STS policy not found (mta-sts.policy-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", strict = false, elapsed = 257ms
2024-11-10T08:40:59Z INFO TLSA record not found (dane.tlsa-record-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx01.mxmail.netease.com", strict = false, elapsed = 245ms
2024-11-10T08:41:00Z INFO Connecting to remote server (delivery.connect) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx01.mxmail.netease.com", localIp = 0.0.0.0, remoteIp = 103.129.252.44, remotePort = 25, elapsed = 223ms
2024-11-10T08:41:01Z INFO STARTTLS error (delivery.start-tls-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx01.mxmail.netease.com", reason = SMTP error occurred (smtp.error) { details = TLS Error, reason = "invalid peer certificate: NotValidForName" }, elapsed = 454ms
2024-11-10T08:41:01Z INFO TLSA record not found (dane.tlsa-record-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", strict = false, elapsed = 273ms
2024-11-10T08:41:02Z INFO Connecting to remote server (delivery.connect) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", localIp = 0.0.0.0, remoteIp = 103.129.252.44, remotePort = 25, elapsed = 218ms
2024-11-10T08:41:03Z INFO STARTTLS error (delivery.start-tls-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", reason = SMTP error occurred (smtp.error) { details = TLS Error, reason = "invalid peer certificate: NotValidForName" }, elapsed = 439ms
2024-11-10T08:41:03Z INFO TLSA record not found (dane.tlsa-record-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx02.mxmail.netease.com", strict = false, elapsed = 252ms
2024-11-10T08:41:03Z INFO Connecting to remote server (delivery.connect) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx02.mxmail.netease.com", localIp = 0.0.0.0, remoteIp = 103.129.252.44, remotePort = 25, elapsed = 215ms
2024-11-10T08:41:04Z INFO Message appended via IMAP (message-ingest.imap-append) listenerId = "imaptls", localPort = 993, remoteIp = 172.17.0.1, remotePort = 60844, accountId = 6, documentId = 43, mailboxId = [4], blobId = "bd915e877e9d799623f76d6ec35d438fca3e6519987318da2b9545a2bfd98c93", changeId = 207509131036823575, messageId = "[email protected]", size = 1123, elapsed = 5ms
2024-11-10T08:41:04Z INFO Full-text search index done (fts-index.index) accountId = 6, collection = email, documentId = 43, elapsed = 1ms
2024-11-10T08:41:04Z INFO STARTTLS error (delivery.start-tls-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx02.mxmail.netease.com", reason = SMTP error occurred (smtp.error) { details = TLS Error, reason = "invalid peer certificate: NotValidForName" }, elapsed = 432ms
2024-11-10T08:41:04Z INFO TLSA record not found (dane.tlsa-record-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx00.mxmail.netease.com", strict = false, elapsed = 262ms
2024-11-10T08:41:05Z INFO Connecting to remote server (delivery.connect) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx00.mxmail.netease.com", localIp = 0.0.0.0, remoteIp = 103.129.252.44, remotePort = 25, elapsed = 207ms
2024-11-10T08:41:06Z INFO STARTTLS error (delivery.start-tls-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx00.mxmail.netease.com", reason = SMTP error occurred (smtp.error) { details = TLS Error, reason = "invalid peer certificate: NotValidForName" }, elapsed = 417ms
2024-11-10T08:41:06Z INFO Message rescheduled for delivery (queue.rescheduled) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, nextRetry = 2024-11-10T08:43:06Z, nextDsn = 2024-11-11T08:40:58Z, expires = 2024-11-15T08:40:58Z
2024-11-10T08:41:06Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, elapsed = 7493ms
2024-11-10T08:43:06Z INFO Delivery attempt started (delivery.attempt-start) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1
2024-11-10T08:43:06Z INFO New delivery attempt for domain (delivery.domain-delivery-start) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", total = 1
2024-11-10T08:43:06Z INFO Error fetching TLS-RPT record (tls-rpt.record-fetch-error) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", causedBy = DNS record not found (mail-auth.dns-record-not-found) { code = No Error }, elapsed = 315ms
2024-11-10T08:43:06Z INFO MTA-STS policy not found (mta-sts.policy-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", strict = false, elapsed = 187ms
2024-11-10T08:43:07Z INFO TLSA record not found (dane.tlsa-record-not-found) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", strict = false, elapsed = 494ms
2024-11-10T08:43:07Z INFO Connecting to remote server (delivery.connect) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", localIp = 0.0.0.0, remoteIp = 103.129.252.44, remotePort = 25, elapsed = 210ms
2024-11-10T08:43:08Z INFO SMTP STARTTLS command (delivery.start-tls) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, domain = "126.com", hostname = "126mx03.mxmail.netease.com", version = "TLSv1_3", details = "TLS13_AES_256_GCM_SHA384", elapsed = 425ms
2024-11-10T08:43:10Z INFO Message delivered (delivery.delivered) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, hostname = "126mx03.mxmail.netease.com", to = "[email protected]", code = 250, details = "Mail OK queued as gzmx10,rikvCgBXFuwbcjBnokilAA--.25851S3 1731228190", elapsed = 1087ms
2024-11-10T08:43:10Z INFO DSN success notification (delivery.dsn-success) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, to = "[email protected]", hostname = "126mx03.mxmail.netease.com", code = 250, details = "Mail OK"
2024-11-10T08:43:10Z INFO Delivery completed (delivery.completed) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, elapsed = 132000ms
2024-11-10T08:43:10Z INFO Delivery attempt ended (delivery.attempt-end) queueId = 207509118789455873, from = "[email protected]", to = ["[email protected]"], size = 1952, total = 1, elapsed = 4836ms
2024-11-10T09:15:00Z INFO ...

Emails sent to 126.com always require two delivery attempts to succeed.
(The email addresses have been anonymized as [email protected] and [email protected].)

Code of Conduct

• I agree to follow this project's Code of Conduct

[mdecimus]

You probably have connectivity or DNS issues.

[ideazh]

I only need one attempt to send to gmail.com successfully, but it always takes two attempts to send to 126.com. I checked the DNS for gmail.com and 126.com as follows:

nslookup -type=txt _mta-sts.gmail.com
_mta-sts.gmail.com	text = "v=STSv1; id=20190429T010101;"

nslookup -type=txt _mta-sts.126.com
*** Can't find _mta-sts.126.com: No answer

It seems that 126.com may have some DNS issues, but the messages are eventually delivered successfully, taking over 2 minutes. Is it possible to optimize this to send successfully within 5 seconds?

[mdecimus]

You can adjust the queue retry times so deliveries are reattempted more often. But if the delay is due to network issues there is not much Stalwart can do.
You can try setting the log level to trace to find out what is taking most time.