Re: Apple mail fails with Submission

Tue, 18 Dec 2018 14:50:00 -0800 

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.tu...@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

Reply via email to