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=t...@example.org <mailto:t...@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=t...@example.org <mailto:t...@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 <step...@rename-it.nl
<mailto:step...@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.voorj...@gmail.com <mailto:ruud.voorj...@gmail.com>
<mailto:ruud.voorj...@gmail.com <mailto: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 <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.tu...@open-xchange.com
<mailto:aki.tu...@open-xchange.com>
<mailto:aki.tu...@open-xchange.com
<mailto:aki.tu...@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
>
