Dear Postfix experts! Although I have found a solution/workaround for the problem mentioned here, for what it's worth, I still wanted to make the effort to report it as a possible bug.
Summary
=======
I have a test setup on my local machine where I am running Postfix and Dovecot,
each in a separate container, for a specialized purpose (not as a public e-Mail
server).
The Postfix container is based on Debian Buster with Postfix 3.4.14 installed
from the default Debian apt repository.
The Dovecot container, reachable via hostname 'dovecot', has an open TCP port
666 for Dovecot SASL, which should be used by Postfix for SMTP Authentication.
Postfix has two smtpd processes configured in master.cf, one for SMTP (port 25,
with STARTTLS) and one for SMTPS (port 465, with implicit TLS).
In main.cf I have configured postfix to use the Dovecot SASL via
smtpd_sasl_path=inet:dovecot:666.
Also, the configuration was initially migrated from an older Postfix version
and was still missing the compatibility_level setting (so default value 0).
Now, when I test the connection using 'openssl s_client' I get two different
behaviors:
* the connection with implicit TLS to port 465 works without a problem, I can
connect incl. TLS handshake, I receive the server greeting and am able to
authenticate
* the connection with explicit TLS (STARTTLS) to port 25 has an issue: I can
connect, the initial EHLO and STARTTLS commands are sent, the TLS handshake is
done, then Postfix aborts the connection.
Solution: When I add compatibility_level=2 to main.cf the connection to port 25
is not aborted after STARTTLS and the TLS handshake and everything works fine.
Initial Configuration
=====================
postfinger - postfix configuration on Tue Aug 10 19:28:18 UTC 2021
version: 1.30
--System Parameters--
mail_version = 3.4.14
hostname = 3e6c12d24f52
uname = Linux 3e6c12d24f52 4.19.128-microsoft-standard #1 SMP Tue Jun 23
12:58:10 UTC 2020 x86_64 GNU/Linux
--Packaging information--
looks like this postfix comes from deb package: postfix-3.4.14-0+deb10u1
--main.cf non-default parameters--
alias_database =
alias_maps =
append_dot_mydomain = no
biff = no
debug_peer_level = 5
debug_peer_list = 0.0.0.0/0
enable_long_queue_ids = yes
local_recipient_maps =
local_transport = error:5.1.1 Mailbox unavailable
maillog_file = /dev/stdout
maximal_queue_lifetime = 100d
message_size_limit = 52428800
mydestination =
protocol_destination_recipient_limit = 1
recipient_bcc_maps = pcre:/etc/postfix/bcc_maps
smtp_host_lookup = native
smtp_tls_loglevel = 2
smtpd_banner = $myhostname ESMTP test server
smtpd_recipient_restrictions = check_recipient_access
pcre:/etc/postfix/bcc_reject
smtpd_relay_restrictions = permit_sasl_authenticated reject_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = inet:dovecot:666
smtpd_sasl_tls_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /etc/pki/tls/certs/hub.pem
smtpd_tls_ciphers = high
smtpd_tls_dh1024_param_file = ${config_directory}/dhparams2048.pem
smtpd_tls_exclude_ciphers = ADH aNULL
smtpd_tls_key_file = /etc/pki/tls/private/hub.key
smtpd_tls_loglevel = 2
smtpd_tls_mandatory_ciphers = $smtpd_tls_ciphers
smtpd_tls_mandatory_exclude_ciphers = $smtpd_tls_exclude_ciphers
smtpd_tls_mandatory_protocols = $smtpd_tls_protocols
smtpd_tls_protocols = !SSLv2 !SSLv3
smtpd_tls_security_level = may
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
tls_preempt_cipherlist = yes
transport_maps = pcre:/etc/postfix/bcc_transport_maps
proxy:pgsql:/etc/postfix/pgsql-transport_maps.cf
virtual_alias_maps = pcre:/etc/postfix/bcc_alias
virtual_mailbox_domains =
proxy:pgsql:/etc/postfix/pgsql-virtual_mailbox_domains.cf
virtual_mailbox_maps = proxy:pgsql:/etc/postfix/pgsql-virtual_mailbox_maps.cf
virtual_transport = lmtp:inet:dovecot
--master.cf--
smtp inet n - - - - smtpd
# Messages received via SMTP should be forwarded to the content filter.
-o content_filter=filter:dummy
# Automatic BCC to protocol should not happen here (only after the content
filter).
-o receive_override_options=no_address_mappings
smtps inet n - n - - smtpd
-o smtpd_tls_wrappermode=yes
# Messages received via SMTP should be forwarded to the content filter.
-o content_filter=filter:dummy
# Automatic BCC to protocol should not happen here (only after the content
filter).
-o receive_override_options=no_address_mappings
pickup unix n - n 60 1 pickup
cleanup unix n - n - 0 cleanup
qmgr unix n - n 300 1 qmgr
tlsmgr unix - - n 1000? 1 tlsmgr
rewrite unix - - n - - trivial-rewrite
bounce unix - - n - 0 bounce
defer unix - - n - 0 bounce
trace unix - - n - 0 bounce
verify unix - - n - 1 verify
flush unix n - n 1000? 0 flush
proxymap unix - - n - - proxymap
proxywrite unix - - n - 1 proxymap
smtp unix - - n - - smtp
showq unix n - n - - showq
error unix - - n - - error
retry unix - - n - - error
discard unix - - n - - discard
local unix - n n - - local
virtual unix - n n - - virtual
lmtp unix - - n - - lmtp
anvil unix - - n - 1 anvil
scache unix - - n - 1 scache
postlog unix-dgram n - n - 1 postlogd
filter unix - n n - 10 pipe
flags=Rq user=filter null_sender=
argv=/etc/postfix/ContentFilter -f ${sender} -- ${recipient}
protocol unix - n n - 10 pipe
flags= user=protocol null_sender=
argv=/etc/postfix/Protocol ${size}
-- end of postfinger output --
Test/Analysis
=============
After issuing this command to establish an implicit TLS connection to the SMTPS
port:
openssl s_client -connect localhost:465
I find the following in the Postfix log output:
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_create:
SASL service=smtp, realm=(null)
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: name_mask: noanonymous
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
Connecting
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: trying... [172.18.0.3]
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: vstream_fflush_some: fd 16
flush 21
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: vstream_buf_get_ready: fd 16
got 114
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: VERSION?1?2
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: MECH?PLAIN?plaintext
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: name_mask: plaintext
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: MECH?LOGIN?plaintext
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: name_mask: plaintext
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: SPID?11
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: CUID?1
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: COOKIE?e732491581051a6edb83b9b3d83b8765
Aug 10 19:33:06 4097ff109d16 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: DONE
Everything works fine in this case.
----------
However, after issuing this command to establish an explicit TLS connection to
the SMTP port:
openssl s_client -connect localhost:25 -starttls smtp
The connection is automatically aborted and I find the following in the Postfix
log output:
Aug 10 19:39:14 4097ff109d16 postfix/smtpd[112]: xsasl_dovecot_server_create:
SASL service=smtp, realm=(null)
Aug 10 19:39:14 4097ff109d16 postfix/smtpd[112]: name_mask: noanonymous
Aug 10 19:39:14 4097ff109d16 postfix/smtpd[112]: xsasl_dovecot_server_connect:
Connecting
Aug 10 19:39:14 4097ff109d16 postfix/smtpd[112]: fatal: host/service
dovecot/666 not found: Device or resource busy
Aug 10 19:39:15 4097ff109d16 postfix/master[1]: warning: process
/usr/lib/postfix/sbin/smtpd pid 112 exit status 1
Aug 10 19:39:15 4097ff109d16 postfix/master[1]: warning:
/usr/lib/postfix/sbin/smtpd: bad command startup -- throttling
As far as I can tell postfix tries to connect to Dovecot SASL to determine the
available authentication methods for responding to the EHLO command sent after
the TLS handshake.
However, it tries to connect to a UNIX socket at dovecot/666 although the
configuration says inet:dovecot:666.
----------
Now, when I make a small modification to the configuration and add only this to
main.cf (and restart postfix):
compatibility_level=2
The following command:
openssl s_client -connect localhost:25 -starttls smtp
Shows nice/working Postfix log output:
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_create:
SASL service=smtp, realm=(null)
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: name_mask: noanonymous
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
Connecting
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: trying... [172.18.0.3]
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: vstream_fflush_some: fd 17
flush 21
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: vstream_buf_get_ready: fd 17
got 114
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: VERSION?1?2
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: MECH?PLAIN?plaintext
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: name_mask: plaintext
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: MECH?LOGIN?plaintext
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: name_mask: plaintext
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: SPID?11
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: CUID?1
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: COOKIE?4b140e8ce85b0aa43e9280ccf136f8c7
Aug 10 19:42:47 722b7fd3dbc1 postfix/smtpd[108]: xsasl_dovecot_server_connect:
auth reply: DONE
And everything works fine afterwards.
----------
Sorry, if this problem is specific to the Debian packages, those are the only
ones I tried obviously.
And sorry, if this problem is already fixed In a newer version of Postfix
(however, I did not find anything related in the release notes of newer
versions).
Best regards
Stefan Podskubka
smime.p7s
Description: S/MIME cryptographic signature
