Why are emails from ProtonMail silently dropped?

public: true
tags: post
Anecdotes
- I didn't receive an email to box from a friend that was using ProtonMail once

Experimenting

Created moreloops@protonmail.com on free plan
Test email format
- Subject: "Testing send from protonmail"
- Body: "Hi myself!" with default signature advertising ProtonMail

Tests, all sent from Protonmail web UI

Email to https://webhook.site email
- Received!
Email to my main gmail
- Received!

Email to my box

Not received

Trying to resolve

Postfix logs: /var/log/mail.log

Jun 23 19:18:00 box postfix/smtpd[31194]: connect from mail-40141.protonmail.ch[185.70.40.141]
Jun 23 19:18:00 box postfix/smtpd[31194]: disconnect from mail-40141.protonmail.ch[185.70.40.141] ehlo=1 starttls=1 quit=1 commands=3
Jun 23 19:18:01 box postfix/smtpd[31194]: connect from mail-0201.mail-europe.com[51.77.79.158]
Jun 23 19:18:02 box postfix/smtpd[31194]: disconnect from mail-0201.mail-europe.com[51.77.79.158] ehlo=1 starttls=1 quit=1 commands=3
Jun 23 19:18:02 box postfix/smtpd[31194]: connect from mail-41103.protonmail.ch[185.70.41.103]
Jun 23 19:18:03 box postfix/smtpd[31194]: disconnect from mail-41103.protonmail.ch[185.70.41.103] ehlo=1 starttls=1 quit=1 commands=3
Jun 23 19:19:49 box postfix/smtpd[31254]: connect from unknown[194.55.186.92]
Jun 23 19:19:50 box postfix/smtpd[31254]: disconnect from unknown[194.55.186.92] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4
Jun 23 19:23:10 box postfix/anvil[31196]: statistics: max connection rate 1/60s for (smtp:185.70.40.141) at Jun 23 19:18:00
Jun 23 19:23:10 box postfix/anvil[31196]: statistics: max connection count 1 for (smtp:185.70.40.141) at Jun 23 19:18:00
Jun 23 19:23:10 box postfix/anvil[31196]: statistics: max cache size 3 at Jun 23 19:18:02
[...]
Jun 23 19:26:24 box postfix/smtpd[32177]: connect from mail-41103.protonmail.ch[185.70.41.103]
Jun 23 19:26:25 box postfix/smtpd[32177]: disconnect from mail-41103.protonmail.ch[185.70.41.103] ehlo=1 starttls=1 quit=1 commands=3
Jun 23 19:28:43 box postfix/smtpd[32180]: connect from unknown[194.55.186.92]
Jun 23 19:28:43 box postfix/smtpd[32180]: disconnect from unknown[194.55.186.92] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4
Jun 23 19:32:04 box postfix/anvil[31781]: statistics: max connection rate 1/60s for (smtp:49.12.57.136) at Jun 23 19:23:56
Jun 23 19:32:04 box postfix/anvil[31781]: statistics: max connection count 1 for (smtp:49.12.57.136) at Jun 23 19:23:56
Jun 23 19:32:04 box postfix/anvil[31781]: statistics: max cache size 2 at Jun 23 19:23:56
Jun 23 19:36:25 box postfix/smtpd[558]: connect from mail-41103.protonmail.ch[185.70.41.103]
Jun 23 19:36:25 box postfix/smtpd[558]: disconnect from mail-41103.protonmail.ch[185.70.41.103] ehlo=1 starttls=1 quit=1 commands=3

Updating Postfix config to log everything

How to get Postfix to log full SMTP connection: https://serverfault.com/a/419829/794150
Steps to test
- Updated /etc/postfix/main.cf to add smtp_tls_loglevel=4
- Ran sudo service postfix reload
- (Realize I forgot the = from the first step)
- Sent email
- Waited a minute
- Removed change from /etc/postfix/main.cf
- Ran sudo service postfix reload
- Tried a few more times (using sudo postfix reload instead for last step)

Got a failed PM send

One failed send at 20:13:02, another at 20:23:02 (exactly 10 minutes apart)

Full logs

Jun 23 20:13:02 box postfix/smtpd[4015]: connect from mail-4327.protonmail.ch[185.70.43.27]
Jun 23 20:13:02 box postfix/smtpd[4015]: smtp_stream_setup: maxtime=300 enable_deadline=0
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? 127.0.0.0/8
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? 127.0.0.0/8
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? [::ffff:127.0.0.0]/104
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? [::ffff:127.0.0.0]/104
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? [::1]/128
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? [::1]/128
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: mail-4327.protonmail.ch: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: 185.70.43.27: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: auto_clnt_open: connected to private/anvil
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = connect
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr ident = smtp:185.70.43.27
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: count
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: count
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 1
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: rate
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: rate
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 1
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: report connect to all milters
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "j"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: result "box.smitop.com"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{daemon_name}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: result "box.smitop.com"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{daemon_addr}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: result "172.16.0.5"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "v"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: result "Postfix 3.3.0"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: non-protocol events for protocol version 6:
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: transport=inet endpoint=127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: trying... [127.0.0.1]
Jun 23 20:13:02 box postfix/smtpd[4015]: vstream_tweak_tcp: TCP_MAXSEG 21845
Jun 23 20:13:02 box postfix/smtpd[4015]: fd=21: stream buffer size old=0 new=43690
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_version=0x6
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_events=0x1fffff SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH SMFIP_NR_HDR SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_RCPT_REJ SMFIP_NR_CONN SMFIP_NR_HELO SMFIP_NR_MAIL SMFIP_NR_RCPT SMFIP_NR_DATA SMFIP_NR_UNKN SMFIP_NR_EOH SMFIP_NR_BODY SMFIP_HDR_LEADSPC
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: milter inet:127.0.0.1:8891 version 6
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: events SMFIP_NOHELO SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_HDR_LEADSPC
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_CHGHDRS SMFIF_SETSYMLIST
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_conn_event: milter inet:127.0.0.1:8891: connect mail-4327.protonmail.ch/185.70.43.27
Jun 23 20:13:02 box postfix/smtpd[4015]: event: SMFIC_CONNECT; macros: j=box.smitop.com {daemon_name}=box.smitop.com {daemon_addr}=172.16.0.5 v=Postfix 3.3.0
Jun 23 20:13:02 box postfix/smtpd[4015]: reply: SMFIR_CONTINUE data 0 bytes
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: non-protocol events for protocol version 6:
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: transport=inet endpoint=127.0.0.1:8893
Jun 23 20:13:02 box postfix/smtpd[4015]: trying... [127.0.0.1]
Jun 23 20:13:02 box postfix/smtpd[4015]: vstream_tweak_tcp: TCP_MAXSEG 21845
Jun 23 20:13:02 box postfix/smtpd[4015]: fd=22: stream buffer size old=0 new=43690
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_version=0x6
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: my_events=0x1fffff SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH SMFIP_NR_HDR SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_RCPT_REJ SMFIP_NR_CONN SMFIP_NR_HELO SMFIP_NR_MAIL SMFIP_NR_RCPT SMFIP_NR_DATA SMFIP_NR_UNKN SMFIP_NR_EOH SMFIP_NR_BODY SMFIP_HDR_LEADSPC
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: milter inet:127.0.0.1:8893 version 6
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: events SMFIP_NOBODY SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_QUARANTINE
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_conn_event: milter inet:127.0.0.1:8893: connect mail-4327.protonmail.ch/185.70.43.27
Jun 23 20:13:02 box postfix/smtpd[4015]: event: SMFIC_CONNECT; macros: j=box.smitop.com {daemon_name}=box.smitop.com {daemon_addr}=172.16.0.5 v=Postfix 3.3.0
Jun 23 20:13:02 box postfix/smtpd[4015]: reply: SMFIR_CONTINUE data 0 bytes
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 220 box.smitop.com ESMTP Hi, I'm a Mail-in-a-Box (Ubuntu/Postfix; see https://mailinabox.email/)
Jun 23 20:13:02 box postfix/smtpd[4015]: watchdog_pat: 0x5639eb654ef0
Jun 23 20:13:02 box postfix/smtpd[4015]: < mail-4327.protonmail.ch[185.70.43.27]: EHLO mail-4327.protonmail.ch
Jun 23 20:13:02 box postfix/smtpd[4015]: report helo to all milters
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{tls_version}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{cipher}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{cipher_bits}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{cert_subject}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter_macro_lookup: "{cert_issuer}"
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_helo_event: milter inet:127.0.0.1:8891: helo mail-4327.protonmail.ch
Jun 23 20:13:02 box postfix/smtpd[4015]: event: SMFIC_HELO; macros: (none)
Jun 23 20:13:02 box postfix/smtpd[4015]: skipping event SMFIC_HELO for milter inet:127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_helo_event: milter inet:127.0.0.1:8893: helo mail-4327.protonmail.ch
Jun 23 20:13:02 box postfix/smtpd[4015]: event: SMFIC_HELO; macros: (none)
Jun 23 20:13:02 box postfix/smtpd[4015]: reply: SMFIR_CONTINUE data 0 bytes
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: mail-4327.protonmail.ch: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: 185.70.43.27: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-box.smitop.com
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-PIPELINING
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-SIZE 134217728
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-VRFY
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-ETRN
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-STARTTLS
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-ENHANCEDSTATUSCODES
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250-8BITMIME
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 250 DSN
Jun 23 20:13:02 box postfix/smtpd[4015]: watchdog_pat: 0x5639eb654ef0
Jun 23 20:13:02 box postfix/smtpd[4015]: < mail-4327.protonmail.ch[185.70.43.27]: STARTTLS
Jun 23 20:13:02 box postfix/smtpd[4015]: query milter states for other event
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_other_event: milter inet:127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_other_event: milter inet:127.0.0.1:8893
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 220 2.0.0 Ready to start TLS
Jun 23 20:13:02 box postfix/smtpd[4015]: abort all milters
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_abort: abort milter inet:127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_abort: abort milter inet:127.0.0.1:8893
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = seed
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr size = 32
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: seed
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: seed
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: [...]
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = tktkey
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr keyname = [data 0 bytes]
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: keybuf
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: keybuf
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: [...]
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = update
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr cache_type = smtpd
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr cache_id = [...]
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr session = [data 137 bytes]
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = update
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr cache_type = smtpd
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr cache_id = [...]
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr session = [data 136 bytes]
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/tlsmgr: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: watchdog_pat: 0x5639eb654ef0
Jun 23 20:13:02 box postfix/smtpd[4015]: < mail-4327.protonmail.ch[185.70.43.27]: QUIT
Jun 23 20:13:02 box postfix/smtpd[4015]: > mail-4327.protonmail.ch[185.70.43.27]: 221 2.0.0 Bye
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? 127.0.0.0/8
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? 127.0.0.0/8
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? [::ffff:127.0.0.0]/104
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? [::ffff:127.0.0.0]/104
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostname: smtpd_client_event_limit_exceptions: mail-4327.protonmail.ch ~? [::1]/128
Jun 23 20:13:02 box postfix/smtpd[4015]: match_hostaddr: smtpd_client_event_limit_exceptions: 185.70.43.27 ~? [::1]/128
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: mail-4327.protonmail.ch: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: match_list_match: 185.70.43.27: no match
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr request = disconnect
Jun 23 20:13:02 box postfix/smtpd[4015]: send attr ident = smtp:185.70.43.27
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: status
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute value: 0
Jun 23 20:13:02 box postfix/smtpd[4015]: private/anvil: wanted attribute: (list terminator)
Jun 23 20:13:02 box postfix/smtpd[4015]: input attribute name: (end)
Jun 23 20:13:02 box postfix/smtpd[4015]: disconnect event to all milters
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_disc_event: quit milter inet:127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: milter8_disc_event: quit milter inet:127.0.0.1:8893
Jun 23 20:13:02 box postfix/smtpd[4015]: disconnect from mail-4327.protonmail.ch[185.70.43.27] ehlo=1 starttls=1 quit=1 commands=3
Jun 23 20:13:02 box postfix/smtpd[4015]: free all milters
Jun 23 20:13:02 box postfix/smtpd[4015]: free milter inet:127.0.0.1:8891
Jun 23 20:13:02 box postfix/smtpd[4015]: free milter inet:127.0.0.1:8893

SMTP commands

SMTP flow extracted from logs

> 220 box.smitop.com ESMTP Hi, I'm a Mail-in-a-Box (Ubuntu/Postfix; see https://mailinabox.email/)
< mail-4327.protonmail.ch[185.70.43.27]: EHLO mail-4327.protonmail.ch
> 250-box.smitop.com
> 250-PIPELINING
> 250-SIZE 134217728
> 250-VRFY
> 250-ETRN
> 250-STARTTLS
> 250-ENHANCEDSTATUSCODES
> 250-8BITMIME
> 250 DSN
< STARTTLS
> 220 2.0.0 Ready to start TLS
[TLS handshake]
< QUIT
> 221 2.0.0 Bye

Immediately quitting after negotiating the TLS handshake?
- TLS isn't completely failing, because it can send a QUIT message over TLS properly
- Tried sending directly to login user, still not delivered with immediate QUIT (two from protonmail.ch 2 seconds apart plus a mail-europe.com one I didn't log (but ehlo=1 starttls=1 quit=1 commands=3 so probably the same))
Theory: ProtonMail is quitting without sending the message for some reason, but still records it as sent
Theory: ProtonMail doesn't like Let's Encrypt certificates
- Check certificate for SMTP server: openssl s_client -connect gmail-smtp-in.l.google.com:25 -starttls smtp
- Seems consistent with what I've observed - my domains, lesswrong.com use Let's Encrypt; no big provider does
- Counterexample: MXroute uses Let's Encrypt but can receive PM emails
- Chains
  - MXroute: ISRG -> E5 -> heracles.mxrouting.net (works)
  - LW: ISRG -> R3 -> *.trikeapps.com (doesn't work)
  - Me: ISRG -> R11 -> box.smitop.com (doesn't work because of werid QUIT)
Other people with the same issue: https://www.google.com/search?q=%22ehlo%3D1+starttls%3D1+quit%3D1+commands%3D3%22
- "I was able to resolve the issue by applying a 'commercial' certificate" - from Outlook https://forums.zimbra.org/viewtopic.php?t=70903
- "Thank sor the tip, it was the TLSA record" - from Outlook https://community.mailcow.email/d/3128-cannot-recieve-mail-from-microsoft-protection-to-specific-domain/14
- "This is what happens if the TLSA RR is invalid" - some university's mailserver https://github.com/docker-mailserver/docker-mailserver/issues/733
- "VPN definitely gets in the way, blocks port 587" - https://forum.iredmail.org/topic16348-mail-client-cant-connect-to-smtp-server.html
- "It was the DANE TLSA records" - Outlook (from MIAB user!) https://discourse.mailinabox.email/t/cannot-receive-emails-from-outlook-microsoft/10238

Email to MXroute handled domain
- Received!
- Nothing concerning in X-Spam-Report
Email to Zoho handled domain
- Received!
Email to NFSN forwarding to Zoho
- Received!

Resolved issue by fixing TLSA record
- Proper value changed at some point, but I never updated the new value in Cloudflare
- Sep 21st, 2024: check if TLSA needs to be updated again