Hello,
I have been migrating away from mailbox and notmuchto dovecot to archive my mail and it works great for this purpose so far! I figured out if I'm proxying IMAP, why not SMTP as well?
Unfortunately that part did not work as well, at least not Migadu that I use as my mail service. I would always get back a
530 5.7.0 authentication required.
from the server when issuing MAIL FROM even though the logs were showing an
apparent success in authenticating. From what I can tell the issue turns out
to be the fact that submission relay sends a fresh EHLO after it has already
successfully authenticated, resetting the state of the connection and dropping
the authentication it just worked to set up. I verified the theory issuing
commands directly to Migadu via openssl s_client:
EHLO, AUTH PLAIN, EHLO, MAIL FROM -> 530 EHLO, AUTH PLAIN, MAIL FROM -> 250
Is it me holding dovecot wrong or a genuine bug? A sanitized log of one tx is appended below.
Thank you, S.
master: Dovecot v2.4.5 (0cbb641e3e) starting up for imap, submission ... submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Server accepted connection (fd=9) submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Connection created submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: Connection created submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: Disconnected submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: Looking up IP address submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: Performing asynchronous DNS lookup submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: conn unix:/run/dovecot2/dns-client: dns(smtp.migadu.com): Lookup started submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: conn unix:/run/dovecot2/dns-client: Connecting submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: conn unix:/run/dovecot2/dns-client (pid=3388288,uid=0): Client connected (fd=15) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: conn unix:/run/dovecot2/dns-client (pid=3388288,uid=0): Sending version handshake submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Connection started submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Sent: 235 2.7.0 Logged in. submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: conn unix:/run/dovecot2/dns-client (pid=3388288,uid=0): dns(smtp.migadu.com): Lookup successful after 4 msecs submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: DNS lookup successful; got 6 IPs submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 [1]: Connecting to 51.210.223.36:465 submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Connecting submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Waiting for connect (fd=8) to finish for max 0 msecs submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: conn unix:/run/dovecot2/dns-client (pid=3388288,uid=0): Disconnected: Connection closed (fd=15) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: conn unix:/run/dovecot2/dns-client (pid=3388288,uid=0): Disconnect: deinit submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Client connected (fd=8) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Starting SSL handshake submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x10, ret=1: before SSL initialization submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: before SSL initialization submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS write client hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS write client hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server hello submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: TLSv1.3 read encrypted extensions submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: Received valid SSL certificate: /C=US/O=Internet Security Research Group/CN=ISRG Root X2 submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: Received valid SSL certificate: /C=US/O=ISRG/CN=Root YE submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: Received valid SSL certificate: /C=US/O=Let's Encrypt/CN=YE1 submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: Received valid SSL certificate: /CN=smtp.migadu.com submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server certificate submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: TLSv1.3 read server certificate verify submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS read finished submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS write change cipher spec submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1001, ret=1: SSLv3/TLS write finished submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x20, ret=1: SSL negotiation finished successfully submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL: where=0x1002, ret=1: SSL negotiation finished successfully submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: SSL handshake successful submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received greeting from server: 220 smtp.migadu.com ESMTP Service Ready submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Sending EHLO handshake submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Submitted with priority submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Sent: EHLO mail.example.com submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Got reply (1/1): 250 smtp.migadu.com Hello mail.example.com PIPELINING 8BITMIME ENHANCEDSTATUSCODES CHUNKING AUTH PLAIN LOGIN AUTH=PLAIN LOGIN SIZE 52428800 (1 commands pending, 0 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received handshake reply submission(me@example.com)<3453761><tfS6...>: Warning: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received invalid EHLO response line: Unexpected character in EHLO keyword submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received server capabilities submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Authenticating as me@example.com submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command AUTH: Submitted with priority submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Destroy (0 commands pending, 1 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command AUTH: Sent: AUTH PLAIN <snip> submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command AUTH: Got reply (1/1): 235 2.0.0 Authentication succeeded (1 commands pending, 0 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Authenticated successfully submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Sending EHLO handshake submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Submitted with priority submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command AUTH: Destroy (0 commands pending, 1 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Sent: EHLO mail.example.com submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Got reply (1/1): 250 smtp.migadu.com Hello mail.example.com PIPELINING 8BITMIME ENHANCEDSTATUSCODES CHUNKING AUTH PLAIN LOGIN AUTH=PLAIN LOGIN SIZE 52428800 (1 commands pending, 0 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received handshake reply submission(me@example.com)<3453761><tfS6...>: Warning: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received invalid EHLO response line: Unexpected character in EHLO keyword submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Received server capabilities submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Connection ready submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Timeout start submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command EHLO: Destroy (0 commands pending, 0 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Received new command: MAIL FROM:<sender@example.com> submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: command MAIL: New command submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: command MAIL: Execute command submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Created submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Start submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Add transaction submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command [plug]: Submitted submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: command MAIL: Next to reply submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Timeout stop submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Start next transaction submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Connection is ready for transaction submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Sending MAIL command submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command MAIL: Submitted submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command [plug]: Aborted submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command [plug]: Removed from send queue submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command [plug]: Destroy (0 commands pending, 1 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command MAIL: Sent: MAIL FROM:<sender@example.com> AUTH=relay@example.com submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Start timeout submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Reset timeout submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command MAIL: Got reply (1/1): 530 5.7.0 authentication required (1 commands pending, 0 commands queued) submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: No commands pending; stop timeout submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Got MAIL reply: 530 5.7.0 authentication required submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Abort submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Abort transaction submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Aborted submission(me@example.com)<3453761><tfS6...>: Error: relay: Server requires authentication: 530 5.7.0 authentication required submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Sent: 421 4.3.5 mail.example.com Internal error occurred. Refer to server log for more information. submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Disconnected: Internal error occurred. Refer to server log for more information. (unfinished MAIL command) (state=MAIL FROM) submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Connection state reset submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: command MAIL: Abort submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: command MAIL: Destroy submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Disconnected submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: smtp.migadu.com: SSL alert: close notify submission(me@example.com)<3453761><tfS6...>: Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Disconnected: Connection closed (fd=8) submission(me@example.com)<3453761><tfS6...>: Disconnected: Internal error occurred. Refer to server log for more information. (unfinished MAIL command) (state=MAIL FROM) in=36 out=124 submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Disconnected: Connection closed (fd=9) submission(me@example.com)<3453761><tfS6...>: Debug: smtp-server: conn 192.168.70.182:50608 [1]: Connection destroy submission(3453761): Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Destroy submission(3453761): Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: transaction: Abort submission(3453761): Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Abort transaction submission(3453761): Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: command MAIL: Destroy (0 commands pending, 0 commands queued) submission(3453761): Debug: relay: smtp-client: conn smtp.migadu.com:465 (51.210.223.36:465) [1]: Destroy