Apple mail fails with Submission
Adi Pircalabu
adi at ddns.com.au
Wed Dec 19 00:48:41 EET 2018
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 = </etc/letsencrypt/live/mail.example.org/fullchain.pem [2]
>> 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 [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 at open-xchange.com>:
>>
>> On 18 December 2018 at 02:30 Adi Pircalabu via dovecot <
>> 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 [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
More information about the dovecot
mailing list