Hey John,
John Stoffel wrote:
"Simonas" == Simonas Kazlauskas via dovecot <dovecot@dovecot.org> writes:
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?
So what are you using to move the mail between the systems? imapsync or some other tool?
This part of report, retrospectively, is not relevant to the issue. Migration itself worked alright and I shouldn't have included this.
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
Again, what tool? Or are you opening the Migadu server using Thunderbird or some other mail client, and then trying to save the email to a new dovecot imap instance?
530 5.7.0 authentication required.
This looks like SMTP commands...
from the server when issuing
MAIL FROMeven 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 viaopenssl s_client:EHLO, AUTH PLAIN, EHLO, MAIL FROM -> 530 EHLO, AUTH PLAIN, MAIL FROM -> 250
Those are SMTP commands.
Is it me holding dovecot wrong or a genuine bug? A sanitized log of one tx is appended below.
You need to explain better what you're trying to do, and how you're doing it. The info you've provided isn't useful without more context and details.
The overarching goal is to have dovecot act as a bidirectional archiving proxy for my mail so that I can connect my mail clients to dovecot only and peruse the entire history of all mail I have collected. Receiving, archiving and reading parts work. Sending via dovecot's SMTP submission-relay did not.
I sent a mail from neomutt (also tried FairEmail) to dovecot's submission-queue (successfully), which would then try to forward the message over to Migadu. This forwarding from the submission relay to migadu is what failed. There are no other tools or services in play for this problem.
The attached log is precisely for one such attempt. Does that help to clarify the report?
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
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org