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 >