search

stalwartlabs / mail-server

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

[bug]: Emails to myself/own account don't seem to work #632

Closed bcspragu closed 3 months ago

bcspragu commented 3 months ago

What happened?

Sending an email from me@example.com to me@example.com doesn't result in any messages in the Inbox. The message, like any sent message, is visible in the Sent folder.

Email on the same local domain (e.g. from a@example.com to b@example.com) work fine.

How can we reproduce the problem?

I can reproduce the problem by doing the following steps:

  1. Send an email to yourself

I tried it in a few different clients (a web client and aerc), both using JMAP (i.e. EmailSubmission/set) to send the request

Version

v0.6.x or lower

What database are you using?

PostgreSQL

What blob storage are you using?

S3-compatible

Where is your directory located?

Internal

What operating system are you using?

Docker

Relevant log output

Here are some logs when sending a message to myself, the logs indicate that it works:

2024-07-16T01:17:34.379352Z  INFO local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::queue::spool: Message queued for delivery. context="queue" event="scheduled" id=186253635393425408 from="<email>@<domain>" nrcpts=1 size=911
2024-07-16T01:17:34.459675Z  INFO delivery{id=186253635393425408 return_path="<email>@<domain>" nrcpt=1 size=911}:attempt{domain="<domain>" attempt_number=0}: smtp::outbound::local: context="deliver_local" event="delivered" rcpt="<email>@<domain>"
2024-07-16T01:17:34.467029Z  INFO delivery{id=186253635393425408 return_path="<email>@<domain>" nrcpt=1 size=911}: smtp::outbound::delivery: Delivery completed. context="queue" event="completed"

Logs are scrubbed to replace something like me@example.com with <email>@<domain>



### Code of Conduct

- [X] I agree to follow this project's Code of Conduct
mdecimus commented 3 months ago

This is a configuration issue. Check your spam folder and if the message is not there set the logging level to trace.

bcspragu commented 3 months ago

I can confirm my junk mailbox is empty, I'll get some new logs at TRACE

mdecimus commented 3 months ago

There should be a log entry indicating that the message has been ingested. This entry includes the account id as well as the mailbox id where the message was stored.

bcspragu commented 3 months ago

Okay, here's the full TRACE logs from sending an email (with a few unrelated log messages):

TRACE level logs from self-email ``` 2024-07-26T16:03:15.899998Z DEBUG jmap::email::ingest: Ingested e-mail. context="email_ingest" event="success" account_id=3 document_id=13156 mailbox_ids=[3] change_id=188177020448935946 blob_id=BlobHash([31, 27, 108, 221, 49, 124, 96, 153, 217, 225, 228, 90, 183, 148, 235, 0, 120, 212, 59, 180, 89, 131, 125, 111, 237, 154, 188, 69, 44, 19, 208, 158]) size=532 2024-07-26T16:03:16.020015Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60816}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:16.024184Z DEBUG jmap::services::index: Indexed document in FTS index context="fts_index_queued" event="index" account_id=3 document_id=13156 2024-07-26T16:03:16.052776Z DEBUG local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::mail: context="mail-from" event="success" address="" 2024-07-26T16:03:16.053190Z TRACE smtp::core::eval: context="eval_if" property="" result=Integer(10) 2024-07-26T16:03:16.053479Z TRACE smtp::core::eval: context="eval_if" property="session.rcpt.errors.wait" result=Integer(5000) 2024-07-26T16:03:16.053657Z TRACE smtp::core::eval: context="eval_if" property="session.rcpt.max-recipients" result=Integer(25) 2024-07-26T16:03:16.053806Z TRACE smtp::core::eval: context="eval_if" property="session.extensions.dsn" result=Integer(1) 2024-07-26T16:03:16.053943Z TRACE smtp::core::eval: context="eval_if" property="session.data.limits.size" result=Integer(104857600) 2024-07-26T16:03:16.054084Z TRACE local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::session: event="write" data="250 2.1.0 OK\r\n" size=14 2024-07-26T16:03:16.054283Z TRACE smtp::core::eval: context="eval_if" property="session.rcpt.directory" result=String("internal") 2024-07-26T16:03:16.063313Z DEBUG local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::rcpt: context="rcpt" event="success" address="" 2024-07-26T16:03:16.063355Z TRACE local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::session: event="write" data="250 2.1.5 OK\r\n" size=14 2024-07-26T16:03:16.065906Z TRACE smtp::core::eval: context="eval_if" property="session.data.limits.received-headers" result=Integer(50) 2024-07-26T16:03:16.065987Z TRACE smtp::core::eval: context="eval_if" property="auth.dkim.verify" result=Integer(2) 2024-07-26T16:03:16.065996Z TRACE smtp::core::eval: context="eval_if" property="auth.dmarc.verify" result=Integer(4) 2024-07-26T16:03:16.066031Z TRACE smtp::core::eval: context="eval_if" property="report.dkim.send" result=Array([Integer(1), Integer(86400000)]) 2024-07-26T16:03:16.066075Z DEBUG local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::data: context="dkim" event="verify" return_path="" from="" result=[] 2024-07-26T16:03:16.066117Z TRACE smtp::core::eval: context="eval_if" property="auth.arc.verify" result=Integer(2) 2024-07-26T16:03:16.066126Z TRACE smtp::core::eval: context="eval_if" property="auth.arc.seal" result=Array([String("rsa")]) 2024-07-26T16:03:16.066138Z DEBUG local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::inbound::data: context="arc" event="verify" return_path="" from="" result=none 2024-07-26T16:03:16.066273Z TRACE smtp::core::eval: context="eval_if" property="session.data.script" result=String("track-replies") 2024-07-26T16:03:16.068872Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60816}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:16.072349Z DEBUG jmap::services::index: Deleted document from FTS index context="fts_index_queued" event="delete" account_id=3 document_id=13153 2024-07-26T16:03:16.078288Z DEBUG local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::scripts::plugins::bayes: context="sieve:bayes_is_balanced" event="result" is_balanced=false learn_spam=false min_balance=0.9 spam_learns=1 ham_learns=3 2024-07-26T16:03:16.078619Z TRACE smtp::core::eval: context="eval_if" property="queue.schedule.notify" result=Array([Integer(86400000), Integer(259200000)]) 2024-07-26T16:03:16.078674Z TRACE smtp::core::eval: context="eval_if" property="queue.schedule.expire" result=Integer(432000000) 2024-07-26T16:03:16.078692Z TRACE smtp::core::eval: context="eval_if" property="session.data.add-headers.received" result=Integer(0) 2024-07-26T16:03:16.078698Z TRACE smtp::core::eval: context="eval_if" property="session.data.add-headers.auth-results" result=Integer(0) 2024-07-26T16:03:16.078703Z TRACE smtp::core::eval: context="eval_if" property="session.data.add-headers.return-path" result=Integer(0) 2024-07-26T16:03:16.078726Z TRACE smtp::core::eval: context="eval_if" property="auth.dkim.sign" result=Array([String("rsa")]) 2024-07-26T16:03:16.228673Z INFO local_delivery{return_path="<>" nrcpt=0 size=0}: smtp::queue::spool: Message queued for delivery. context="queue" event="scheduled" id=188177021304573952 from="" nrcpts=1 size=1081 2024-07-26T16:03:16.246655Z TRACE smtp::core::eval: context="eval_if" property="queue.outbound.next-hop" result=String("local") 2024-07-26T16:03:16.357671Z DEBUG jmap::email::ingest: Duplicate message skipped. context="email_ingest" event="skip" account_id=3 from=Some(List([Addr { name: None, address: Some("")}])) message_id="17e5cec9198d11c2.479a492aa16b2b3a.5ddefc818e6a5acc@de4b5fe416b6" 2024-07-26T16:03:16.357761Z INFO delivery{id=188177021304573952 return_path="" nrcpt=1 size=1081}:attempt{domain="" attempt_number=0}: smtp::outbound::local: context="deliver_local" event="delivered" rcpt="" 2024-07-26T16:03:16.357783Z TRACE smtp::core::eval: context="eval_if" property="queue.schedule.retry" result=Array([Integer(120000), Integer(300000), Integer(600000), Integer(900000), Integer(1800000), Integer(3600000), Integer(7200000)]) 2024-07-26T16:03:16.365579Z INFO delivery{id=188177021304573952 return_path="" nrcpt=1 size=1081}: smtp::outbound::delivery: Delivery completed. context="queue" event="completed" 2024-07-26T16:03:16.403761Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60830}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:16.454117Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60830}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:17.872846Z DEBUG utils::listener::listen: Dropping connection from blocked IP. context="listener" event="blocked" instance="submissions" protocol=Smtp remote.ip="194.169.175.33" remote.port=45970 2024-07-26T16:03:18.040156Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60830}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:18.040156Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60816}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:18.087548Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60830}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:18.096120Z DEBUG session{instance="jmap-http-caddy" protocol=Jmap remote.ip="172.18.0.4" remote.port=60816}: jmap::api::http: event="request" uri="/jmap/" 2024-07-26T16:03:23.345606Z DEBUG utils::listener::listen: Dropping connection from blocked IP. context="listener" event="blocked" instance="submissions" protocol=Smtp remote.ip="194.169.175.47" remote.p ```

I'm not sure what everything means, but the smoking gun might be:

2024-07-26T16:03:16.357671Z DEBUG jmap::email::ingest: Duplicate message skipped. context="email_ingest" event="skip" account_id=3 from=Some(List([Addr { name: None, address: Some("<THE EMAIL>")}])) message_id="17e5cec9198d11c2.479a492aa16b2b3a.5ddefc818e6a5acc@de4b5fe416b6"

Any ideas? Could it be that, because the message is already in the Sent mailbox, it's being dropped and never hitting the Inbox?

mdecimus commented 3 months ago

That warning means that there is already a message in your inbox with the same Message-Id header.

bcspragu commented 3 months ago

Looking at the logic, the deduplication only seems to check for the Message-Id behavior, not what mailbox it is in: https://github.com/stalwartlabs/mail-server/blob/ea77a982608d396f3990d53be000a11266542fdc/crates/jmap/src/email/ingest.rs#L152-L175

So I think what I said above holds true:

  1. We send a message to ourselves
  2. As part of sending, we move the message from Drafts to Sent
  3. We then go to ingest the message, and find that the message ID already exists (in Sent)

I don't know how other mail providers handle this, but self-email seems to be a common way people send notes to themselves, and it does work on other mail providers (e.g. Gmail). Not sure if the correct approach is to special-case self-email, or to move a duplicated email to the inbox if some conditions hold, or what, but I think this should affect any Stalwart deployment.

mdecimus commented 3 months ago

I have just changed the filter to include the target mailbox on the duplicate check.