Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org[xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
I think it is some kind of bug or maybe it just isn't supported (yet), cause as you said it is still "pretty basic".
Best Regards
On 2018-12-18 07:33, Ruud Voorjans wrote:
Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
Hi,
did you see this thread?
https://dovecot.org/list/dovecot/2018-October/113348.html https://dovecot.org/list/dovecot/2018-October/113348.html
Had a similar issue with CHUNKING and Apple Mail, but could reproduce it with a Perl script, too. But I do not whether this was fixed already in v2.3.4 (nothing found in the release notes). Could be that relaying PIPELINING hast the same issues with “multi-line replies”.
Regards, Paul
On 18. Dec 2018, at 07:18, Aki Tuomi aki.tuomi@open-xchange.com wrote:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org mailto:dovecot@dovecot.org> wrote:
Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient. Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and
On 2018-12-18 07:33, Ruud Voorjans wrote: the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings.
Aki Tuomi
Paul Hecker paul@iwascoding.com mailto:paul@iwascoding.com http://www.iwascoding.com http://www.iwascoding.com/
iwascoding GmbH Weserstr 18, 10247 Berlin HRB 97269 B Amtsgericht Berlin-Charlottenburg Geschäftsführer: Paul Hecker, Ilja Iwas
Op 18/12/2018 om 10:18 schreef Paul Hecker via dovecot:
Hi,
did you see this thread?
https://dovecot.org/list/dovecot/2018-October/113348.html
Had a similar issue with CHUNKING and Apple Mail, but could reproduce it with a Perl script, too. But I do not whether this was fixed already in v2.3.4 (nothing found in the release notes). Could be that relaying PIPELINING hast the same issues with “multi-line replies”.
I'm not sure yet that this is the same problem. That fix is indeed not released yet. It is in the pipeline. From the looks of things, it should be in v2.3.5.
Regards,
Stephan.
On 18. Dec 2018, at 07:18, Aki Tuomi
mailto:aki.tuomi@open-xchange.com> wrote: On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org mailto:dovecot@dovecot.org> wrote:
Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org http://mail.example.org [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient. Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and
On 2018-12-18 07:33, Ruud Voorjans wrote: the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings.
Aki Tuomi
Paul Hecker paul@iwascoding.com mailto:paul@iwascoding.com http://www.iwascoding.com http://www.iwascoding.com/
iwascoding GmbH Weserstr 18, 10247 Berlin HRB 97269 B Amtsgericht Berlin-Charlottenburg Geschäftsführer: Paul Hecker, Ilja Iwas
doveconf -n output: # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.2 () # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 # Hostname: mail.example.org auth_debug = yes auth_debug_passwords = yes auth_mechanisms = plain login auth_verbose = yes director_mail_servers = XX.XX.XX.XX hostname = mail.example.org log_path = /var/log/dovecot.log login_trusted_networks = XX.XX.XX.XX mail_debug = yes mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = proxy=y host=XX.XX.XX nopassword=y driver = static } protocols = imap submission service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service submission-login { executable = submission-login } ssl = required ssl_cert =
Logging: Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection created Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [10.225.11.41] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org 8BITMIME BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: STARTTLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Next to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation now. Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Starting TLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection clear Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [XX.XX.XX.XX] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org 8BITMIME AUTH PLAIN LOGIN BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: AUTH PLAIN Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Next to reply Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN service=submission secured=tls session= lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 rport=49679 local_name= mail.example.org ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= (previous base64 data may contain sensitive data) Dec 18 16:36:39 auth: Debug: static(): lookup Dec 18 16:36:39 auth: Debug: static(): Allowing any password Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 user= proxy host= XX.XX.XX.XX pass= Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Destroy Dec 18 16:36:39 submission-login: Info: proxy( ): started proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Disconnected: Connection closed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify
Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi aki.tuomi@open-xchange.com:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org> wrote:
On 2018-12-18 07:33, Ruud Voorjans wrote:
Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings.
Aki Tuomi
Postfix debug peer logging
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org[XX.XX.XX.XX]: 250 2.1.5 Ok Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 28 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 15 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org [ XX.XX.XX.XX]: BDAT 326 LAST Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? connect Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? get Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? post Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_list_match: BDAT: no match Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org [ XX.XX.XX.XX] : 502 5.5.2 Error: command not recognized Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 41 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 326 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: warning: non-SMTP command from server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org [ XX.XX.XX.XX] ]: 221 2.7.0 Error: I can break rules, too. Goodbye.
Op di 18 dec. 2018 om 17:01 schreef Ruud Voorjans ruud.voorjans@gmail.com:
doveconf -n output: # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.2 () # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 # Hostname: mail.example.org auth_debug = yes auth_debug_passwords = yes auth_mechanisms = plain login auth_verbose = yes director_mail_servers = XX.XX.XX.XX hostname = mail.example.org log_path = /var/log/dovecot.log login_trusted_networks = XX.XX.XX.XX mail_debug = yes mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = proxy=y host=XX.XX.XX nopassword=y driver = static } protocols = imap submission service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service submission-login { executable = submission-login } ssl = required ssl_cert =
Logging: Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection created Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [10.225.11.41] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org 8BITMIME BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: STARTTLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Next to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation now. Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Starting TLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection clear Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [XX.XX.XX.XX] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org 8BITMIME AUTH PLAIN LOGIN BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: AUTH PLAIN Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Next to reply Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN service=submission secured=tls session= lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 rport=49679 local_name= mail.example.org ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= (previous base64 data may contain sensitive data) Dec 18 16:36:39 auth: Debug: static(): lookup Dec 18 16:36:39 auth: Debug: static(): Allowing any password Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 user= proxy host= XX.XX.XX.XX pass= Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Destroy Dec 18 16:36:39 submission-login: Info: proxy( ): started proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Disconnected: Connection closed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify
Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi
:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org> wrote:
On 2018-12-18 07:33, Ruud Voorjans wrote:
Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings.
Aki Tuomi
On 2018-12-19 03:17, Ruud Voorjans wrote:
Postfix debug peer logging
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org [4][XX.XX.XX.XX]: 250 2.1.5 Ok Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 28 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 15 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org [4] [ XX.XX.XX.XX]: BDAT 326 LAST Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? connect Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? get Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? post Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_list_match: BDAT: no match Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org [4] [ XX.XX.XX.XX] : 502 5.5.2 Error: command not recognized Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 41 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 326 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org [4] [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: warning: non-SMTP command from server.example.org [4] [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org [4] [ XX.XX.XX.XX] ]: 221 2.7.0 Error: I can break rules, too. Goodbye.
Do you have the submission logs for the same timestamp? You server doesn't support BDAT command. However, looking at the logs below I have a suspicion your submission is advertising CHUNKING incorrectly. Misconfiguration or bug? https://tools.ietf.org/html/rfc1830
-- Adi Pircalabu
Op di 18 dec. 2018 om 17:01 schreef Ruud Voorjans
doveconf -n output: # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.2 () # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 # Hostname: mail.example.org [1] auth_debug = yes auth_debug_passwords = yes auth_mechanisms = plain login auth_verbose = yes director_mail_servers = XX.XX.XX.XX hostname = mail.example.org [1] log_path = /var/log/dovecot.log login_trusted_networks = XX.XX.XX.XX mail_debug = yes mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = proxy=y host=XX.XX.XX nopassword=y driver = static } protocols = imap submission service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service submission-login { executable = submission-login } ssl = required ssl_cert =
AES256+EECDH:AES256+EDH:ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:ECDH+3DES:DH+3DES:RSA+AESGCM:RSA+AES:RSA+3DES:!aNULL:!MD5
ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_min_protocol = TLSv1.2 ssl_prefer_server_ciphers = yes submission_relay_host = XX.XX.XX.XX submission_relay_rawlog_dir = /var/log/dovecot.log submission_relay_trusted = yes verbose_ssl = yes
Logging: Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection created Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [10.225.11.41] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org [3] 8BITMIME BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: STARTTLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Next to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation now. Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Starting TLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection clear Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [XX.XX.XX.XX] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org [3] 8BITMIME AUTH PLAIN LOGIN BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: AUTH PLAIN Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Next to reply Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN service=submission secured=tls session= lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 rport=49679 local_name=mail.example.org [1] ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= (previous base64 data may contain sensitive data) Dec 18 16:36:39 auth: Debug: static(): lookup Dec 18 16:36:39 auth: Debug: static(): Allowing any password Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 user= proxy host= XX.XX.XX.XX pass= Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Destroy Dec 18 16:36:39 submission-login: Info: proxy( ): started proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Disconnected: Connection closed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify
Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi aki.tuomi@open-xchange.com:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org> wrote:
On 2018-12-18 07:33, Ruud Voorjans wrote: Dear all,
I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone).
I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org [1] [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit""
with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient. Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address.
Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows.
-- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings.
Aki Tuomi
Links:
[1] http://mail.example.org [2] http://mail.example.org/fullchain.pem [3] http://250-mail.example.org [4] http://server.example.org
Hi,
Below, you have only the submission-login debug log (authentication). I'm more interested in what happens after that. You'll need to enable mail_debug=yes (at least for the user involved) to get that.
Regards,
Stephan.
Op 18/12/2018 om 17:17 schreef Ruud Voorjans:
Postfix debug peer logging
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org[XX.XX.XX.XX]: 250 2.1.5 Ok Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 28 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 15 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org http://server.example.org [ XX.XX.XX.XX]: BDAT 326 LAST Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? connect Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? get Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? post Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_list_match: BDAT: no match Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org [ XX.XX.XX.XX] : 502 5.5.2 Error: command not recognized Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 41 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 326 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org http://server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: warning: non-SMTP command from server.example.org http://server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org [ XX.XX.XX.XX] ]: 221 2.7.0 Error: I can break rules, too. Goodbye.
Op di 18 dec. 2018 om 17:01 schreef Ruud Voorjans
mailto:ruud.voorjans@gmail.com>: doveconf -n output: # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.2 () # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 # Hostname: mail.example.org <http://mail.example.org> auth_debug = yes auth_debug_passwords = yes auth_mechanisms = plain login auth_verbose = yes director_mail_servers = XX.XX.XX.XX hostname = mail.example.org <http://mail.example.org> log_path = /var/log/dovecot.log login_trusted_networks = XX.XX.XX.XX mail_debug = yes mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = proxy=y host=XX.XX.XX nopassword=y driver = static } protocols = imap submission service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service submission-login { executable = submission-login } ssl = required ssl_cert = </etc/letsencrypt/live/mail.example.org/fullchain.pem <http://mail.example.org/fullchain.pem> ssl_cipher_list = AES256+EECDH:AES256+EDH:ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:ECDH+3DES:DH+3DES:RSA+AESGCM:RSA+AES:RSA+3DES:!aNULL:!MD5 ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_min_protocol = TLSv1.2 ssl_prefer_server_ciphers = yes submission_relay_host = XX.XX.XX.XX submission_relay_rawlog_dir = /var/log/dovecot.log submission_relay_trusted = yes verbose_ssl = yes Logging: Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection created Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [10.225.11.41] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> 8BITMIME BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: STARTTLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Next to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation now. Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Starting TLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection clear Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [XX.XX.XX.XX] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> 8BITMIME AUTH PLAIN LOGIN BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: AUTH PLAIN Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Next to reply Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN service=submission secured=tls session= lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 rport=49679 local_name=mail.example.org <http://mail.example.org> ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= (previous base64 data may contain sensitive data) Dec 18 16:36:39 auth: Debug: static(): lookup Dec 18 16:36:39 auth: Debug: static(): Allowing any password Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 user= proxy host= XX.XX.XX.XX pass= Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Destroy Dec 18 16:36:39 submission-login: Info: proxy( ): started proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Disconnected: Connection closed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi <aki.tuomi@open-xchange.com <mailto:aki.tuomi@open-xchange.com>>:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org <mailto:dovecot@dovecot.org>> wrote: On 2018-12-18 07:33, Ruud Voorjans wrote:
Dear all, I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone). I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org <http://mail.example.org> [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit"" with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address. Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows. -- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings. --- Aki Tuomi
After the submission with dovecot it sends it to postfix, the postfix log is:
postfix/submission/smtpd[19509]: connect from example.org[192.168.1.1] postfix/submission/smtpd[19509]: client=example.org[192.168.1.1], sasl_method=PLAIN, sasl_username=test@example.org postfix/submission/smtpd[19509]: *warning: non-SMTP command from example.org http://example.org[192.168.1.1]: Content-Transfer-Encoding: 7bit* postfix/submission/smtpd[19509]: disconnect from example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 unknown=0/2 commands=4/6 postfix/submission/smtpd[19509]: connect from example.org[192.168.1.1] postfix/submission/smtpd[19509]: client=example.org[192.168.1.1], sasl_method=PLAIN, sasl_username=test@example.org postfix/submission/smtpd[19509]: *warning: non-SMTP command from example.org http://example.org[192.168.1.1]: Content-Type: text/plain; charset=us-ascii* postfix/submission/smtpd[19509]: disconnect from example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 unknown=0/2 commands=4/6 postfix/submission/smtpd[18882]: *timeout after END-OF-MESSAGE from example.org http://example.org[192.168.1.1]* postfix/submission/smtpd[18882]: disconnect from example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 data=1 commands=5
As you can see it is a "non-SMTP command" given by Postfix. Am guessing it has something to do with the placement of the mail content. The outlook application is functional normally, i upgraded to 2.3.4 of Dovecot but still same result.
Not sure if it is a Dovecot issue or Postfix..
On Sun, Dec 23, 2018 at 11:46 AM Stephan Bosch stephan@rename-it.nl wrote:
Hi,
Below, you have only the submission-login debug log (authentication). I'm more interested in what happens after that. You'll need to enable mail_debug=yes (at least for the user involved) to get that.
Regards,
Stephan.
Op 18/12/2018 om 17:17 schreef Ruud Voorjans:
Postfix debug peer logging
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org[XX.XX.XX.XX]: 250 2.1.5 Ok Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 28 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 15 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org http://server.example.org [ XX.XX.XX.XX]: BDAT 326 LAST Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? connect Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? get Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: smtpd_forbidden_commands: bdat ~? post Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_list_match: BDAT: no match Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org [ XX.XX.XX.XX] : 502 5.5.2 Error: command not recognized Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: 0x55ef4ec020180 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_fflush_some: fd 10 flush 41 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: vstream_buf_get_ready: fd 10 got 326 Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < server.example.org http://server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: warning: non-SMTP command from server.example.org http://server.example.org [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > server.example.org http://server.example.org [ XX.XX.XX.XX] ]: 221 2.7.0 Error: I can break rules, too. Goodbye.
Op di 18 dec. 2018 om 17:01 schreef Ruud Voorjans
mailto:ruud.voorjans@gmail.com>: doveconf -n output: # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.2 () # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 # Hostname: mail.example.org <http://mail.example.org> auth_debug = yes auth_debug_passwords = yes auth_mechanisms = plain login auth_verbose = yes director_mail_servers = XX.XX.XX.XX hostname = mail.example.org <http://mail.example.org> log_path = /var/log/dovecot.log login_trusted_networks = XX.XX.XX.XX mail_debug = yes mail_location = mbox:~/mail:INBOX=/var/mail/%u mail_privileged_group = mail namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = proxy=y host=XX.XX.XX nopassword=y driver = static } protocols = imap submission service director { fifo_listener login/proxy-notify { mode = 0600 user = $default_login_user } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director } service submission-login { executable = submission-login } ssl = required ssl_cert = </etc/letsencrypt/live/mail.example.org/fullchain.pem <http://mail.example.org/fullchain.pem> ssl_cipher_list =
AES256+EECDH:AES256+EDH:ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:ECDH+3DES:DH+3DES:RSA+AESGCM:RSA+AES:RSA+3DES:!aNULL:!MD5
ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_min_protocol = TLSv1.2 ssl_prefer_server_ciphers = yes submission_relay_host = XX.XX.XX.XX submission_relay_rawlog_dir = /var/log/dovecot.log submission_relay_trusted = yes verbose_ssl = yes Logging: Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection created Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [10.225.11.41] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> 8BITMIME BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: STARTTLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Next to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation now. Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Starting TLS Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection clear Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command STARTTLS; 220 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: before SSL initialization Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server hello Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write certificate Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write server done Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=-1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read client key exchange Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS read finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write change cipher spec Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: SSLv3/TLS write finished Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: SSL negotiation finished successfully Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: EHLO [XX.XX.XX.XX] Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> 8BITMIME AUTH PLAIN LOGIN BURL imap CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command EHLO; 250 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: No more commands pending Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Received new command: AUTH PLAIN Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Next to reply Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN service=submission secured=tls session= lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 rport=49679 local_name=mail.example.org <http://mail.example.org> ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= (previous base64 data may contain sensitive data) Dec 18 16:36:39 auth: Debug: static(): lookup Dec 18 16:36:39 auth: Debug: static(): Allowing any password Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 user= proxy host= XX.XX.XX.XX pass= Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Submitted Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Ready to reply Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Trigger output Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Sending replies Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Completed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH: Destroy Dec 18 16:36:39 submission-login: Info: proxy( ): started proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Disconnected: Connection closed Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: command AUTH; 235 reply: Destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection destroy Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: Connection state reset Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi <aki.tuomi@open-xchange.com <mailto:aki.tuomi@open-xchange.com>>:
On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < dovecot@dovecot.org <mailto:dovecot@dovecot.org>> wrote: On 2018-12-18 07:33, Ruud Voorjans wrote:
Dear all, I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () - OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. It works great except with apple mail (Iphone). I get an error with the MTA (postfix): ""postfix/submission/smtpd[32552]: warning: non-SMTP command from mail.example.org <http://mail.example.org> [1][xx.xx.xx.xx]: Content-Transfer-Encoding: 7bit"" with other mail-client(s) (Outlook (Desktop and Iphone app)) i have no problem and it proxy-sends the e-mail beautiful out to the recipient.
Hardly anything to do with Dovecot. When it comes to email clients Apple Mail has been and is still one of the worst flops (no offence intended, just my opinion based on personal experience). If you can reliably reproduce it, try and log the raw SMTP conversation between Postfix and the client by enabling per IP debugging in Postfix: postconf -e "debug_peer_level = 20" postconf -e "debug_peer_list = xx.xx.xx.xx" postfix reload where xx.xx.xx.xx is the unlucky client IP address. Possibly some crappy SMTP PIPELINING implementation at the Apple end, who knows. -- Adi Pircalabu
It's not unconceivable that there are bugs in submission either. Can you provide doveconf -n and submission rawlogs? See https://wiki.dovecot.org/Submission for settings. --- Aki Tuomi
Op 07/01/2019 om 21:54 schreef Ruud Voorjans:
After the submission with dovecot it sends it to postfix, the postfix log is:
postfix/submission/smtpd[19509]: connect from example.org http://example.org[192.168.1.1] postfix/submission/smtpd[19509]: client=example.org http://example.org[192.168.1.1], sasl_method=PLAIN, sasl_username=test@example.org mailto:test@example.org postfix/submission/smtpd[19509]: *warning: non-SMTP command from example.org http://example.org[192.168.1.1]: Content-Transfer-Encoding: 7bit* postfix/submission/smtpd[19509]: disconnect from example.org http://example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 unknown=0/2 commands=4/6 postfix/submission/smtpd[19509]: connect from example.org http://example.org[192.168.1.1] postfix/submission/smtpd[19509]: client=example.org http://example.org[192.168.1.1], sasl_method=PLAIN, sasl_username=test@example.org mailto:test@example.org postfix/submission/smtpd[19509]: *warning: non-SMTP command from example.org http://example.org[192.168.1.1]: Content-Type: text/plain; charset=us-ascii* postfix/submission/smtpd[19509]: disconnect from example.org http://example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 unknown=0/2 commands=4/6 postfix/submission/smtpd[18882]: *timeout after END-OF-MESSAGE from example.org http://example.org[192.168.1.1]* postfix/submission/smtpd[18882]: disconnect from example.org http://example.org[192.168.1.1] ehlo=1 auth=1 mail=1 rcpt=1 data=1 commands=5
As you can see it is a "non-SMTP command" given by Postfix. Am guessing it has something to do with the placement of the mail content. The outlook application is functional normally, i upgraded to 2.3.4 of Dovecot but still same result.
Not sure if it is a Dovecot issue or Postfix..
Yeah, but I was asking for a debug log from the Dovecot submission service. :) You sent a debug log from submission-login before, which doesn't help me, because it doesn't directly talk to Postfix.
Regards,
Stephan.
On Sun, Dec 23, 2018 at 11:46 AM Stephan Bosch
mailto:stephan@rename-it.nl> wrote: Hi, Below, you have only the submission-login debug log (authentication). I'm more interested in what happens after that. You'll need to enable mail_debug=yes (at least for the user involved) to get that. Regards, Stephan. Op 18/12/2018 om 17:17 schreef Ruud Voorjans: > Postfix debug peer logging > > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > > server.example.org <http://server.example.org> <http://server.example.org>[XX.XX.XX.XX]: 250 2.1.5 Ok > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: > 0x55ef4ec020180 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > vstream_fflush_some: fd 10 flush 28 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > vstream_buf_get_ready: fd 10 got 15 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < > server.example.org <http://server.example.org> <http://server.example.org> [ XX.XX.XX.XX]: BDAT > 326 LAST > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: > smtpd_forbidden_commands: bdat ~? connect > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: > smtpd_forbidden_commands: bdat ~? get > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: match_string: > smtpd_forbidden_commands: bdat ~? post > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > match_list_match: BDAT: no match > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > > server.example.org <http://server.example.org> <http://server.example.org> [ XX.XX.XX.XX] : 502 > 5.5.2 Error: command not recognized > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: watchdog_pat: > 0x55ef4ec020180 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > vstream_fflush_some: fd 10 flush 41 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > vstream_buf_get_ready: fd 10 got 326 > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: < > server.example.org <http://server.example.org> <http://server.example.org> [ XX.XX.XX.XX] : > Content-Type: text/plain; charset=us-ascii > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: warning: > non-SMTP command from server.example.org <http://server.example.org> <http://server.example.org> > [ XX.XX.XX.XX] : Content-Type: text/plain; charset=us-ascii > Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > > server.example.org <http://server.example.org> <http://server.example.org> [ XX.XX.XX.XX] ]: 221 > 2.7.0 Error: I can break rules, too. Goodbye. > > > Op di 18 dec. 2018 om 17:01 schreef Ruud Voorjans > <ruud.voorjans@gmail.com <mailto:ruud.voorjans@gmail.com> <mailto:ruud.voorjans@gmail.com <mailto:ruud.voorjans@gmail.com>>>: > > doveconf -n output: > # 2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf > # Pigeonhole version 0.5.2 () > # OS: Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 > # Hostname: mail.example.org <http://mail.example.org> <http://mail.example.org> > auth_debug = yes > auth_debug_passwords = yes > auth_mechanisms = plain login > auth_verbose = yes > director_mail_servers = XX.XX.XX.XX > hostname = mail.example.org <http://mail.example.org> <http://mail.example.org> > log_path = /var/log/dovecot.log > login_trusted_networks = XX.XX.XX.XX > mail_debug = yes > mail_location = mbox:~/mail:INBOX=/var/mail/%u > mail_privileged_group = mail > namespace inbox { > inbox = yes > location = > mailbox Drafts { > special_use = \Drafts > } > mailbox Junk { > special_use = \Junk > } > mailbox Sent { > special_use = \Sent > } > mailbox "Sent Messages" { > special_use = \Sent > } > mailbox Trash { > special_use = \Trash > } > prefix = > } > passdb { > args = proxy=y host=XX.XX.XX nopassword=y > driver = static > } > protocols = imap submission > service director { > fifo_listener login/proxy-notify { > mode = 0600 > user = $default_login_user > } > inet_listener { > port = 9090 > } > unix_listener director-userdb { > mode = 0600 > } > unix_listener login/director { > mode = 0666 > } > } > service imap-login { > executable = imap-login director > } > service submission-login { > executable = submission-login > } > ssl = required > ssl_cert = </etc/letsencrypt/live/mail.example.org/fullchain.pem <http://mail.example.org/fullchain.pem> > <http://mail.example.org/fullchain.pem> > ssl_cipher_list = > AES256+EECDH:AES256+EDH:ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:ECDH+3DES:DH+3DES:RSA+AESGCM:RSA+AES:RSA+3DES:!aNULL:!MD5 > ssl_dh = # hidden, use -P to show it > ssl_key = # hidden, use -P to show it > ssl_min_protocol = TLSv1.2 > ssl_prefer_server_ciphers = yes > submission_relay_host = XX.XX.XX.XX > submission_relay_rawlog_dir = /var/log/dovecot.log > submission_relay_trusted = yes > verbose_ssl = yes > > > Logging: > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection created > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Received new command: EHLO [10.225.11.41] > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Submitted > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Ready to reply > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Completed > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection state reset > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> > <http://250-mail.example.org> 8BITMIME BURL imap CHUNKING > ENHANCEDSTATUSCODES SIZE STARTTLS PIPELINING > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Received new command: STARTTLS > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS: Next to reply > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS; 220 reply: Submitted > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS: Ready to reply > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS; 220 reply: Sent: 220 2.0.0 Begin TLS negotiation > now. > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Starting TLS > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection clear > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection state reset > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command STARTTLS; 220 reply: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x10, ret=1: > before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > before SSL initialization > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS read client hello > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write server hello > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write certificate > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write server done > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, > ret=-1: SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS read client key exchange > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS read change cipher spec > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS read finished > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write change cipher spec > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2001, ret=1: > SSLv3/TLS write finished > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x20, ret=1: > SSL negotiation finished successfully > Dec 18 16:36:39 submission-login: Debug: SSL: where=0x2002, ret=1: > SSL negotiation finished successfully > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Received new command: EHLO [XX.XX.XX.XX] > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Submitted > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Ready to reply > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Completed > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection state reset > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Sent: 250-mail.example.org <http://250-mail.example.org> > <http://250-mail.example.org> 8BITMIME AUTH PLAIN LOGIN BURL imap > CHUNKING ENHANCEDSTATUSCODES SIZE PIPELINING > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command EHLO; 250 reply: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > No more commands pending > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Received new command: AUTH PLAIN > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH: Next to reply > Dec 18 16:36:39 auth: Debug: client in: AUTH 1 PLAIN > service=submission secured=tls session= > lip=XX.XX.XX.XX rip=XX.XX.XX.XX lport=587 > rport=49679 local_name=mail.example.org <http://mail.example.org> > <http://mail.example.org> ssl_cipher=ECDHE-RSA-AES256-GCM-SHA384 > ssl_cipher_bits=256 ssl_pfs= ssl_protocol=TLSv1.2 resp= > (previous base64 data may contain sensitive data) > Dec 18 16:36:39 auth: Debug: static(): lookup > Dec 18 16:36:39 auth: Debug: static(): Allowing any password > Dec 18 16:36:39 auth: Debug: client passdb out: OK 1 > user= proxy host= XX.XX.XX.XX pass= > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH; 235 reply: Submitted > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH: Ready to reply > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Trigger output > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Sending replies > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH: Completed > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH; 235 reply: Sent: 235 2.7.0 Authentication successful > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH: Destroy > Dec 18 16:36:39 submission-login: Info: proxy( ): started > proxying to XX.XX.XX.XX:587: user=< >, method=PLAIN, > rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, session=<> > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Disconnected: Connection closed > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > command AUTH; 235 reply: Destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection destroy > Dec 18 16:36:39 submission-login: Debug: smtp-server: conn [0]: > Connection state reset > Dec 18 16:36:40 submission-login: Info: proxy( ): disconnecting > XX.XX.XX.XX (Disconnected by server(0s idle, in=533, out=295)): > user=< >, method=PLAIN, rip=XX.XX.XX.XX, lip=XX.XX.XX.XX, TLS, > session=<> > Dec 18 16:36:40 submission-login: Debug: SSL alert: close notify > > > Op di 18 dec. 2018 om 07:18 schreef Aki Tuomi > <aki.tuomi@open-xchange.com <mailto:aki.tuomi@open-xchange.com> <mailto:aki.tuomi@open-xchange.com <mailto:aki.tuomi@open-xchange.com>>>: > > >> On 18 December 2018 at 02:30 Adi Pircalabu via dovecot < >> dovecot@dovecot.org <mailto:dovecot@dovecot.org> <mailto:dovecot@dovecot.org <mailto:dovecot@dovecot.org>>> wrote: >> >> >> On 2018-12-18 07:33, Ruud Voorjans wrote: >>> Dear all, >>> >>> I'm running dovecot # 2.3.2.1 - Pigeonhole version 0.5.2 () >>> - OS: >>> Linux 4.18.0-12-generic x86_64 Ubuntu 18.10 with Submission. >>> It works great except with apple mail (Iphone). >>> >>> I get an error with the MTA (postfix): >>> ""postfix/submission/smtpd[32552]: warning: non-SMTP command >>> from >>> mail.example.org <http://mail.example.org> <http://mail.example.org> [1][xx.xx.xx.xx]: >>> Content-Transfer-Encoding: 7bit"" >>> >>> with other mail-client(s) (Outlook (Desktop and Iphone app)) >>> i have no >>> problem and it proxy-sends the e-mail beautiful out to the >>> recipient. >> Hardly anything to do with Dovecot. When it comes to email >> clients Apple >> Mail has been and is still one of the worst flops (no offence >> intended, >> just my opinion based on personal experience). If you can >> reliably >> reproduce it, try and log the raw SMTP conversation between >> Postfix and >> the client by enabling per IP debugging in Postfix: >> postconf -e "debug_peer_level = 20" >> postconf -e "debug_peer_list = xx.xx.xx.xx" >> postfix reload >> where xx.xx.xx.xx is the unlucky client IP address. >> >> Possibly some crappy SMTP PIPELINING implementation at the >> Apple end, >> who knows. >> >> -- >> Adi Pircalabu > > It's not unconceivable that there are bugs in submission > either. Can you provide doveconf -n and submission rawlogs? > See https://wiki.dovecot.org/Submission for settings. > > --- > Aki Tuomi >
participants (5)
-
Adi Pircalabu
-
Aki Tuomi
-
Paul Hecker
-
Ruud Voorjans
-
Stephan Bosch