SMTP over TLS fails only when using local email clients (logs attached)

[eaerhaerhaehae aehraerhaeha]

I can send emails over port 465 using smtper.net  just fine. It's the clients (thunderbird, k-9,..) that cause an error when there is supposed to be EHLO.
STARTTLS works perfectly for both, dovecot and postfix. TLS works perfectly for dovecot. Only postfix TLS is giving me trouble.
What could be the problem here?
Thanks!

 
NOT WORKING CONNECTION FROM MY PC/PHONE ("Thunderbird failed to find the settings for your email account.")
---------------------------------------------------------------------------------

Sep  7 02:42:49 myserver postfix/smtpd[20128]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
Sep  7 02:42:49 myserver postfix/smtpd[20128]: xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]: ???
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ??? ~? connect
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ??? ~? get
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ??? ~? post
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ???: no match
Sep  7 02:42:49 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]: 502 5.5.2 Error: command not recognized
Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]: ??????
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? connect
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? get
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? post
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ?: no match
Sep  7 02:42:49 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]: 502 5.5.2 Error: command not recognized
Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]: ?
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? connect
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? get
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string: smtpd_forbidden_commands: ? ~? post
Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ?: no match
Sep  7 02:42:49 myserver dovecot: imap-login: Aborted login (no auth attempts in 1 secs): user=<>, rip=1.2.3.4, lip=my.server.ip.here, TLS, session=<2ZdzST117MJXe3ri>
Sep  7 02:42:54 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]: 502 5.5.2 Error: command not recognized
Sep  7 02:42:59 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]: 421 4.7.0 mx.my-email-server.com Error: too many errors
---------------------------------------------------------------------------------
 

WORKING CONNECTION FROM SMTPER
---------------------------------------------------------------------------------

Sep  7 02:46:51 myserver postfix/smtpd[20169]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
Sep  7 02:46:51 myserver postfix/smtpd[20169]: xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
Sep  7 02:46:51 myserver postfix/smtpd[20169]: < ns513574.ip-192-99-9.net[192.99.9.142]: EHLO SkyWeb
Sep  7 02:46:51 myserver postfix/smtpd[20169]: match_list_match: ns513574.ip-192-99-9.net: no match
Sep  7 02:46:51 myserver postfix/smtpd[20169]: match_list_match: 192.99.9.142: no match
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-mx.my-email-server.com
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-PIPELINING
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-SIZE 100000000
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-ETRN
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-AUTH PLAIN LOGIN
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-AUTH=PLAIN LOGIN
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-ENHANCEDSTATUSCODES
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250-8BITMIME
Sep  7 02:46:51 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 250 DSN
Sep  7 02:46:52 myserver postfix/smtpd[20169]: < ns513574.ip-192-99-9.net[192.99.9.142]: AUTH login ZW1haWxAbXktZW1haWwtc2VydmVyLmNvbQ==
Sep  7 02:46:52 myserver postfix/smtpd[20169]: xsasl_dovecot_server_first: sasl_method login, init_response ZW1haWxAbXktZW1haWwtc2VydmVyLmNvbQ==
Sep  7 02:46:52 myserver postfix/smtpd[20169]: xsasl_dovecot_handle_reply: auth reply: CONT?1?UGFzc3dvcmQ6
Sep  7 02:46:52 myserver postfix/smtpd[20169]: > ns513574.ip-192-99-9.net[192.99.9.142]: 334 UGFzc3dvcmQ6
Sep  7 02:46:52 myserver postfix/smtpd[20169]: < ns513574.ip-192-99-9.net[192.99.9.142]: MTIzNDU=
Sep  7 02:46:52 myserver postfix/smtpd[20169]: xsasl_dovecot_handle_reply: auth reply: OK?1?user=[hidden email]?
---------------------------------------------------------------------------------

[Miwa Susumu]

Hi.

2018-09-07 11:06 GMT+09:00 eaerhaerhaehae aehraerhaeha <[hidden email]>:
> I can send emails over port 465 using smtper.net  just fine. It's the clients (thunderbird, k-9,..) that cause an error when there is supposed to be EHLO.
> STARTTLS works perfectly for both, dovecot and postfix. TLS works perfectly for dovecot. Only postfix TLS is giving me trouble.
> What could be the problem here?
> Thanks!
>

Can you capture e-mail packets from client to server ? (use wireshark etc...)

--
miwarin

[Bill Cole-3]

On 6 Sep 2018, at 22:06 (-0400), eaerhaerhaehae aehraerhaeha wrote:

> I can send emails over port 465 using smtper.net  just fine. It's the
> clients (thunderbird, k-9,..) that cause an error when there is
> supposed to be EHLO.
> STARTTLS works perfectly for both, dovecot and postfix. TLS works
> perfectly for dovecot. Only postfix TLS is giving me trouble.
> What could be the problem here?
> Thanks!
>
>  
> NOT WORKING CONNECTION FROM MY PC/PHONE ("Thunderbird failed to find
> the settings for your email account.")

That sounds like a TBird problem. Postfix has nothing to do with
providing settings for TBird or any other MUA.

> ---------------------------------------------------------------------------------
>
> Sep  7 02:42:49 myserver postfix/smtpd[20128]:
> xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
> Sep  7 02:42:49 myserver postfix/smtpd[20128]:
> xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]:
> ???
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ??? ~? connect
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ??? ~? get
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ??? ~? post
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ???:
> no match
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]:
> 502 5.5.2 Error: command not recognized
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]:
> ??????
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? connect
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? get
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? post
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ?:
> no match
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: > my.isp.com[1.2.3.4]:
> 502 5.5.2 Error: command not recognized
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: < my.isp.com[1.2.3.4]:
> ?
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? connect
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? get
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_string:
> smtpd_forbidden_commands: ? ~? post
> Sep  7 02:42:49 myserver postfix/smtpd[20128]: match_list_match: ?:
> no match
> Sep  7 02:42:49 myserver dovecot: imap-login: Aborted login (no auth
> attempts in 1 secs): user=<>, rip=1.2.3.4, lip=my.server.ip.here, TLS,
> session=<2ZdzST117MJXe3ri>

This looks like one of 2 common problems:

1. The MUA is trying to use immediate TLS ("smtps" or "wrappermode" in
postfix-ese) on port 25 or 587, rather than on port 465, which is the
only place where it is usable.

2. You have a very dumb firewall (e.g. Cisco ASA or ancient Cisco PIX)
misconfigured to "protect" your mail server.

This looks MUCH more like (1) to me...

Solution: fix your client settings. Don't use wrappermode on anything
but port 465 *configured* for wrappermode.


> WORKING CONNECTION FROM SMTPER
[...]

> Sep  7 02:46:52 myserver postfix/smtpd[20169]: <
> ns513574.ip-192-99-9.net[192.99.9.142]: AUTH login
> ZW1haWxAbXktZW1haWwtc2VydmVyLmNvbQ==
> Sep  7 02:46:52 myserver postfix/smtpd[20169]:
> xsasl_dovecot_server_first: sasl_method login, init_response
> ZW1haWxAbXktZW1haWwtc2VydmVyLmNvbQ==
> Sep  7 02:46:52 myserver postfix/smtpd[20169]:
> xsasl_dovecot_handle_reply: auth reply: CONT?1?UGFzc3dvcmQ6
> Sep  7 02:46:52 myserver postfix/smtpd[20169]: >
> ns513574.ip-192-99-9.net[192.99.9.142]: 334 UGFzc3dvcmQ6
> Sep  7 02:46:52 myserver postfix/smtpd[20169]: <
> ns513574.ip-192-99-9.net[192.99.9.142]: MTIzNDU=
> Sep  7 02:46:52 myserver postfix/smtpd[20169]:
> xsasl_dovecot_handle_reply: auth reply:
> OK?1?user=[hidden email]?
> ---------------------------------------------------------------------------------

If you didn't munge the above to make it look like you use a supremely
bad password, you need to stop using such a supremely bad password...


For further assistance, you should provide the information noted in the
last section Postfix DEBUG_README documentation.



--
Bill Cole
[hidden email] or [hidden email]
(AKA @grumpybozo and many *@billmail.scconsult.com addresses)
Currently Seeking Steadier Work: https://linkedin.com/in/billcole