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=t...@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=t...@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 <step...@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 > > <ruud.voorj...@gmail.com <mailto:ruud.voorj...@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.tu...@open-xchange.com <mailto:aki.tu...@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 > > >
