Apple mail fails with Submission
Ruud Voorjans
ruud.voorjans at gmail.com
Mon Jan 7 22:54:17 EET 2019
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 at 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 at 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 at 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.voorjans at gmail.com <mailto:ruud.voorjans at 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 at open-xchange.com <mailto:aki.tuomi at open-xchange.com>>:
> >
> >
> >> On 18 December 2018 at 02:30 Adi Pircalabu via dovecot <
> >> dovecot at dovecot.org <mailto:dovecot at 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
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20190107/b105d8e2/attachment-0001.html>
More information about the dovecot
mailing list