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:
