Postfix smtp gets stuck with XCLIENT when using smtps

[Aki Tuomi]

Hi!

I stumbled upon a possible bug with postfix. I am using postfix 3.4.14, and when I use XCLIENT command over smtps (not starttls), the session gets stuck until further input, which causes it to abort the connection due to unexpected SSL packet.

--
Aki Tuomi

## postconf -nf
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
compatibility_level = 2
default_transport = error
inet_interfaces = loopback-only
inet_protocols = all
mailbox_size_limit = 0
mydestination = $myhostname, dev04.dovecot.net, localhost.dovecot.net, localhost
myhostname = dev04.dovecot.net
mynetworks = 127.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128
myorigin = /etc/mailname
readme_directory = no
recipient_delimiter = +
relay_transport = error
relayhost =
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_authorized_xclient_hosts = 127.0.0.1,[::1]
smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated
      defer_unauth_destination
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot
smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-snakeoil.pem
smtpd_tls_key_file = /etc/ssl/private/ssl-cert-snakeoil.key
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_use_tls = yes
virtual_mailbox_domains = example.org
virtual_transport = lmtp:localhost:24

## postconf -Mf

smtp          inet   n          -          y          -          -          smtpd
525            inet   n          -          y          -          -          smtpd
      -o syslog_name=postfix/submission
      -o smtpd_tls_wrappermode=yes
      -o smtpd_tls_security_level=encrypt
      -o smtpd_sasl_auth_enable=yes
      -o smtpd_reject_unlisted_recipient=no
      -o smtpd_recipient_restrictions=
      -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
      -o milter_macro_daemon_name=ORIGINATING
      -o debug_peer_level=9
      -o debug_peer_list=127.0.0.1,[::1]
pickup       unix   n          -          y          60         1          pickup
cleanup      unix   n          -          y          -          0          cleanup
qmgr          unix   n          -          n          300       1          qmgr
tlsmgr       unix   -          -          y          1000?    1          tlsmgr
rewrite      unix   -          -          y          -          -          trivial-rewrite
bounce       unix   -          -          y          -          0          bounce
defer         unix   -          -          y          -          0          bounce
trace         unix   -          -          y          -          0          bounce
verify       unix   -          -          y          -          1          verify
flush         unix   n          -          y          1000?    0          flush
proxymap    unix   -          -          n          -          -          proxymap
proxywrite unix   -          -          n          -          1          proxymap
smtp          unix   -          -          y          -          -          smtp
relay         unix   -          -          y          -          -          smtp
showq         unix   n          -          y          -          -          showq
error         unix   -          -          y          -          -          error
retry         unix   -          -          y          -          -          error
discard      unix   -          -          y          -          -          discard
local         unix   -          n          n          -          -          local
virtual      unix   -          n          n          -          -          virtual
lmtp          unix   -          -          y          -          -          lmtp
anvil         unix   -          -          y          -          1          anvil
scache       unix   -          -          y          -          1          scache

## mail log

Oct 22 18:13:33 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 220 dev04.dovecot.net ESMTP Postfix (Debian/GNU)
Oct 22 18:13:33 dev04 postfix/submission/smtpd[11290]: watchdog_pat: 0x5570313f6a40
Oct 22 18:13:33 dev04 postfix/submission/smtpd[11290]: vstream_fflush_some: fd 17 flush 50
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: vstream_buf_get_ready: fd 17 got 15
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: < localhost[::1]: EHLO localhost
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: match_list_match: localhost: no match
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: match_list_match: ::1: no match
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-dev04.dovecot.net
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-PIPELINING
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-SIZE 10240000
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-VRFY
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-ETRN
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-AUTH PLAIN LOGIN XOAUTH2 OAUTHBEARER
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-XCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT LOGIN
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-ENHANCEDSTATUSCODES
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-8BITMIME
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250-DSN
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: >  localhost[::1]: 250 SMTPUTF8
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: watchdog_pat: 0x5570313f6a40
Oct 22 18:13:35 dev04 postfix/submission/smtpd[11290]: vstream_fflush_some: fd 17 flush 240
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: vstream_buf_get_ready: fd 17 got 31
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: < localhost[::1]: XCLIENT ADDR=1.2.3.4 PORT=1234
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_hostname: smtpd_authorized_xclient_hosts: localhost ~? 127.0.0.1
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_hostaddr: smtpd_authorized_xclient_hosts: 1.2.3.4 ~? 127.0.0.1
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_hostname: smtpd_authorized_xclient_hosts: localhost ~? [::1]
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_hostaddr: smtpd_authorized_xclient_hosts: 1.2.3.4 ~? [::1]
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_list_match: localhost: no match
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: match_list_match: 1.2.3.4: no match
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: xsasl_dovecot_server_create: SASL service=smtp, realm=(null)
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: name_mask: noanonymous
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: xsasl_dovecot_server_mech_filter: keep mechanism: PLAIN
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: xsasl_dovecot_server_mech_filter: keep mechanism: LOGIN
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: xsasl_dovecot_server_mech_filter: keep mechanism: XOAUTH2
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: xsasl_dovecot_server_mech_filter: keep mechanism: OAUTHBEARER
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: event_request_timer: reset 0x7f0560d6fb60 0x5570313d7600 5
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: send attr request = seed
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: send attr size = 32
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: vstream_fflush_some: fd 12 flush 22
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: vstream_buf_get_ready: fd 12 got 60
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: private/tlsmgr: wanted attribute: status
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: input attribute name: status
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: input attribute value: 0
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: private/tlsmgr: wanted attribute: seed
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: input attribute name: seed
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: input attribute value: QPjjgohy0bl1TpWD/VvRKljOZ47rMGxuW6K8ZU08YOM=
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: private/tlsmgr: wanted attribute: (list terminator)
Oct 22 18:13:41 dev04 postfix/submission/smtpd[11290]: input attribute name: (end)
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: SSL_accept error from localhost[1.2.3.4]: -1
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: warning: TLS library problem: error:140940F4:SSL routines:ssl3_read_bytes:unexpected message:../ssl/record/rec_layer_s3.c:1218:
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.0/8
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostaddr: smtpd_client_event_limit_exceptions: 1.2.3.4 ~? 127.0.0.0/8
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? [::ffff:127.0.0.0]/104
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostaddr: smtpd_client_event_limit_exceptions: 1.2.3.4 ~? [::ffff:127.0.0.0]/104
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? [::1]/128
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_hostaddr: smtpd_client_event_limit_exceptions: 1.2.3.4 ~? [::1]/128
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_list_match: localhost: no match
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: match_list_match: 1.2.3.4: no match
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: auto_clnt_open: connected to private/anvil
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: event_enable_read: fd 19
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: send attr request = disconnect
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: send attr ident = 525:1.2.3.4
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: vstream_fflush_some: fd 19 flush 38
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: vstream_buf_get_ready: fd 19 got 10
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: private/anvil: wanted attribute: status
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: input attribute name: status
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: input attribute value: 0
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: private/anvil: wanted attribute: (list terminator)
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: input attribute name: (end)
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: lost connection after XCLIENT from localhost[1.2.3.4]
Oct 22 18:14:23 dev04 postfix/submission/smtpd[11290]: disconnect from localhost[1.2.3.4] ehlo=1 xclient=0/1 commands=1/2

## connection log

$ openssl s_client -connect localhost:585
220 dev04.dovecot.net ESMTP Postfix (Debian/GNU)
EHLO localhost
250-dev04.dovecot.net
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-AUTH PLAIN LOGIN XOAUTH2 OAUTHBEARER
250-XCLIENT NAME ADDR PROTO HELO REVERSE_NAME PORT LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 SMTPUTF8
XCLIENT ADDR=1.2.3.4 PORT=1234
AUTH PLAIN
140319306629184:error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac:../ssl/record/ssl3_record.c:469:

[Wietse Venema]

Aki Tuomi:
> Hi!
>
> I stumbled upon a possible bug with postfix. I am using postfix
> 3.4.14, and when I use XCLIENT command over smtps (not starttls),
> the session gets stuck until further input, which causes it to
> abort the connection due to unexpected SSL packet.

The server is waiting for a TLS handshake.

By design, XCLIENT resets the session state to where it was immediately
after the SMTP client connected. Otherwise, things like milters and
smtpd_client_restrictions would not work porperly. Therefore, the
first thing the SMTPS server will do is wait for a TLS handshake.

Fixed by selectively skipping the TLS handshake.

        Wietse

diff -ur /var/tmp/postfix-3.6-20201003/src/smtpd/smtpd.c src/smtpd/smtpd.c
--- /var/tmp/postfix-3.6-20201003/src/smtpd/smtpd.c 2020-10-03 17:53:03.000000000 -0400
+++ src/smtpd/smtpd.c 2020-10-22 15:57:33.506845176 -0400
@@ -5464,7 +5464,8 @@
  * obsolete, so we don't have to provide perfect support.
  */
 #ifdef USE_TLS
- if (SMTPD_STAND_ALONE(state) == 0 && var_smtpd_tls_wrappermode) {
+ if (SMTPD_STAND_ALONE(state) == 0 && var_smtpd_tls_wrappermode
+    && state->tls_context == 0) {
 #ifdef USE_TLSPROXY
     /* We garbage-collect the VSTREAM in smtpd_state_reset() */
     state->tlsproxy =

[Demi M. Obenour]

On 10/22/20 12:47 PM, Aki Tuomi wrote:
> Hi!
>
> I stumbled upon a possible bug with postfix. I am using postfix 3.4.14, and when I use XCLIENT command over smtps (not starttls), the session gets stuck until further input, which causes it to abort the connection due to unexpected SSL packet.

Just FYI, gmail marked this message as spam.  Not sure why.

Demi

[Bastian Blank-3]

On Fri, Oct 23, 2020 at 11:55:20AM -0400, Demi M. Obenour wrote:
> On 10/22/20 12:47 PM, Aki Tuomi wrote:
> > I stumbled upon a possible bug with postfix. I am using postfix 3.4.14, and when I use XCLIENT command over smtps (not starttls), the session gets stuck until further input, which causes it to abort the connection due to unexpected SSL packet.
> Just FYI, gmail marked this message as spam.  Not sure why.

Maybe your setup is wrong.  Talk to gmail if you want to know more.
However you don't need to send the same message all the time.

Bastian

--
Fascinating is a word I use for the unexpected.
                -- Spock, "The Squire of Gothos", stardate 2124.5