Postfix debug peer logging
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: >
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
[ 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
[ 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
[ 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 [ XX.XX.XX.XX] : Content-Type:
text/plain; charset=us-ascii
Dec 18 17:08:11 mail postfix/submission/smtpd[10626]: > 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>:
> 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
> 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
> 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
> 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 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 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 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][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
>>
>
