Postfix 3.5.5 and TLS handshake failure

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Postfix 3.5.5 and TLS handshake failure

Christos Chatzaras
Few hours ago I upgrade from Postfix 3.5.4 to 3.5.5 and sometimes I get "Cannot start TLS: handshake failure":

------
Jul 26 13:21:10 smtp2 postfix/smtpd[26600]: 1DB241F4EA: client=server28.example.net[138.201.82.xxx]
Jul 26 13:21:10 smtp2 postfix/cleanup[26147]: 1DB241F4EA: message-id=<[hidden email]>
Jul 26 13:21:10 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
Jul 26 13:21:10 smtp2 relay2/smtp[26609]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=0.42, delays=0.4/0/0.02/0, dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
Jul 26 13:26:50 smtp2 relay4/smtp[26535]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=341, delays=340/0/0.04/0.53, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
as 6F1B02869AA)
Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: removed
------

These messages are delivered the next time the sender SMTP tries to deliver the message.


Also I use Monit to monitor Postfix and after the upgrade to 3.5.5 version I get messages like this:

------
Connection failed Service postfix
 Date: Sun, 26 Jul 2020 14:01:39
 Action: restart
 Host: server28.example.com
 Description: failed protocol test [SMTP] at [127.0.0.1]:25 [TCP/IP] -- Error receiving data from the mailserver -- Resource temporarily unavailable
------


Is this a known issue?
Reply | Threaded
Open this post in threaded view
|

Re: Postfix 3.5.5 and TLS handshake failure

Christos Chatzaras

Few hours ago I upgrade from Postfix 3.5.4 to 3.5.5 and sometimes I get "Cannot start TLS: handshake failure":

------
Jul 26 13:21:10 smtp2 postfix/smtpd[26600]: 1DB241F4EA: client=server28.example.net[138.201.82.xxx]
Jul 26 13:21:10 smtp2 postfix/cleanup[26147]: 1DB241F4EA: message-id=<[hidden email]>
Jul 26 13:21:10 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
Jul 26 13:21:10 smtp2 relay2/smtp[26609]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=0.42, delays=0.4/0/0.02/0, dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
Jul 26 13:26:50 smtp2 relay4/smtp[26535]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=341, delays=340/0/0.04/0.53, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
as 6F1B02869AA)
Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: removed
------

These messages are delivered the next time the sender SMTP tries to deliver the message.


Also I use Monit to monitor Postfix and after the upgrade to 3.5.5 version I get messages like this:

------
Connection failed Service postfix
Date: Sun, 26 Jul 2020 14:01:39
Action: restart
Host: server28.example.com
Description: failed protocol test [SMTP] at [127.0.0.1]:25 [TCP/IP] -- Error receiving data from the mailserver -- Resource temporarily unavailable
------


Is this a known issue?

Also the logs are full of these messages:

postfix/master[83315]: warning: process /usr/local/libexec/postfix/smtpd pid 53056 killed by signal 11

And here is a bug report in FreeBSD which I think is the same issue:


Reply | Threaded
Open this post in threaded view
|

Re: Postfix 3.5.5 and TLS handshake failure

Jim Maenpaa


> On Jul 26, 2020, at 06:33, Christos Chatzaras <[hidden email]> wrote:
>
>>
>> Few hours ago I upgrade from Postfix 3.5.4 to 3.5.5 and sometimes I get "Cannot start TLS: handshake failure":
>>
>> ------
>> Jul 26 13:21:10 smtp2 postfix/smtpd[26600]: 1DB241F4EA: client=server28.example.net[138.201.82.xxx]
>> Jul 26 13:21:10 smtp2 postfix/cleanup[26147]: 1DB241F4EA: message-id=<[hidden email]>
>> Jul 26 13:21:10 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
>> Jul 26 13:21:10 smtp2 relay2/smtp[26609]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=0.42, delays=0.4/0/0.02/0, dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
>> Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
>> Jul 26 13:26:50 smtp2 relay4/smtp[26535]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=341, delays=340/0/0.04/0.53, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
>> as 6F1B02869AA)
>> Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: removed
>> ------
>>
>> These messages are delivered the next time the sender SMTP tries to deliver the message.
>>
>>
>> Also I use Monit to monitor Postfix and after the upgrade to 3.5.5 version I get messages like this:
>>
>> ------
>> Connection failed Service postfix
>> Date: Sun, 26 Jul 2020 14:01:39
>> Action: restart
>> Host: server28.example.com
>> Description: failed protocol test [SMTP] at [127.0.0.1]:25 [TCP/IP] -- Error receiving data from the mailserver -- Resource temporarily unavailable
>> ------
>>
>>
>> Is this a known issue?
>
> Also the logs are full of these messages:
>
> postfix/master[83315]: warning: process /usr/local/libexec/postfix/smtpd pid 53056 killed by signal 11
>
> And here is a bug report in FreeBSD which I think is the same issue:
>
> https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=248271
>

I am seeing two different issues like this after upgrading to 3.5.5. I am only seeing these after when the smtpd process had processed one or more messages and is doing the TLS handshake for another message.

In this first case, all of the servers are mine, all are using Postfix 3.5.5, and all have valid certificates:

Jul 26 03:55:42 morbo postfix/smtpd[61854]: connect from ndnd.ohwell.org[2001:19f0:5c01:384::1]
Jul 26 03:55:42 morbo postfix/smtpd[61854]: Anonymous TLS connection established from ndnd.ohwell.org[2001:19f0:5c01:384::1]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256
Jul 26 03:55:42 morbo postfix/smtpd[61854]: 4BF0GQ2nzfzwC5: client=ndnd.ohwell.org[2001:19f0:5c01:384::1]
Jul 26 03:55:42 morbo postfix/smtpd[61854]: disconnect from ndnd.ohwell.org[2001:19f0:5c01:384::1] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jul 26 03:57:18 morbo postfix/smtpd[61854]: connect from guenter.ohwell.org[45.76.79.194]
Jul 26 03:57:18 morbo postfix/smtpd[61854]: SSL_accept error from guenter.ohwell.org[45.76.79.194]: -1
Jul 26 03:57:18 morbo postfix/smtpd[61854]: warning: TLS library problem: error:14094412:SSL routines:ssl3_read_bytes:sslv3 alert bad certificate:/usr/src/crypto/openssl/ssl/record/rec_layer_s3.c:1544:SSL alert number 42:
Jul 26 03:57:18 morbo postfix/master[49852]: warning: process /usr/local/libexec/postfix/smtpd pid 61854 killed by signal 10

In this second case, only the receiving server is mine:

Jul 26 06:57:41 morbo postfix/smtpd[73115]: connect from o1.emailer.networkforgood.com[167.89.13.177]
Jul 26 06:57:41 morbo postfix/smtpd[73115]: Anonymous TLS connection established from o1.emailer.networkforgood.com[167.89.13.177]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jul 26 06:57:42 morbo postfix/smtpd[73115]: 4BF4JQ29DLzwPX: client=o1.emailer.networkforgood.com[167.89.13.177]
Jul 26 06:57:44 morbo postfix/smtpd[73115]: disconnect from o1.emailer.networkforgood.com[167.89.13.177] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jul 26 06:57:44 morbo postfix/smtpd[73115]: connect from xbdu.email-messaging.com[159.135.236.93]
Jul 26 06:57:44 morbo postfix/smtpd[73115]: Anonymous TLS connection established from xbdu.email-messaging.com[159.135.236.93]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256
Jul 26 06:57:45 morbo postfix/smtpd[73115]: 4BF4JT2ZF5zwPY: client=xbdu.email-messaging.com[159.135.236.93]
Jul 26 07:00:05 morbo postfix/smtpd[73115]: disconnect from xbdu.email-messaging.com[159.135.236.93] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jul 26 07:00:37 morbo postfix/smtpd[73115]: connect from st11p00im-ztba01351701.me.com[17.172.82.217]
Jul 26 07:00:37 morbo postfix/smtpd[73115]: SSL_accept error from st11p00im-ztba01351701.me.com[17.172.82.217]: -1
Jul 26 07:00:37 morbo postfix/smtpd[73115]: warning: TLS library problem: error:1417A0C1:SSL routines:tls_post_process_client_hello:no shared cipher:/usr/src/crypto/openssl/ssl/statem/statem_srvr.c:2259:
Jul 26 07:00:37 morbo postfix/master[49852]: warning: process /usr/local/libexec/postfix/smtpd pid 73115 killed by signal 11

When the me.com server tries again, the TLS handshake works:

Jul 26 07:10:34 morbo postfix/smtpd[73299]: Anonymous TLS connection established from st11p00im-ztba01351701.me.com[17.172.82.217]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jul 26 07:10:34 morbo postfix/smtpd[73299]: 4BF4bG2wSxzwPm: client=st11p00im-ztba01351701.me.com[17.172.82.217]

-jim

Reply | Threaded
Open this post in threaded view
|

Re: Postfix 3.5.5 and TLS handshake failure

Yasuhiro KIMURA
In reply to this post by Christos Chatzaras
From: Christos Chatzaras <[hidden email]>
Subject: Re: Postfix 3.5.5 and TLS handshake failure
Date: Sun, 26 Jul 2020 16:33:33 +0300

> Also the logs are full of these messages:
>
> postfix/master[83315]: warning: process /usr/local/libexec/postfix/smtpd pid 53056 killed by signal 11
>
> And here is a bug report in FreeBSD which I think is the same issue:
>
> https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=248271

I'm reporter of it. Following is output of postfinger on this server.

----------------------------------------------------------------------
postfinger - postfix configuration on Mon Jul 27 01:00:22 JST 2020
version: 1.30

Warning: postfinger output may show private configuration information,
such as ip addresses and/or domain names which you do not want to show
to the public.  If this is the case it is your responsibility to modify
the output to hide this private information.  [Remove this warning with
the --nowarn option.]

--System Parameters--
mail_version = 3.5.5
hostname = eastasia.home.utahime.org
uname = FreeBSD eastasia.home.utahime.org 12.1-RELEASE-p7 FreeBSD 12.1-RELEASE-p7 GENERIC  amd64

--Packaging information--

--main.cf non-default parameters--
alias_database = hash:/etc/mail/aliases
alias_maps = hash:/etc/mail/aliases
compatibility_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5
inet_protocols = ipv4
mailbox_command_maps = hash:/usr/local/etc/postfix/mailbox_commands
mydestination = /etc/mail/local-host-names
mynetworks = 192.168.0.0/24, 127.0.0.0/8
myorigin = $mydomain
non_smtpd_milters = unix:/var/run/clamav/clmilter.sock
relayhost = mail-relay.home.utahime.org
smtp_tls_CAfile = /etc/ssl/cert.pem
smtp_tls_ciphers = high
smtp_tls_loglevel = 1
smtp_tls_mandatory_ciphers = high
smtp_tls_mandatory_protocols = !SSLv2 !SSLv3 !TLSv1 !TLSv1.1
smtp_tls_protocols = !SSLv2 !SSLv3 !TLSv1 !TLSv1.1
smtp_tls_security_level = may
smtpd_milters = unix:/var/run/clamav/clmilter.sock inet:localhost:11332
smtpd_sasl_path = private/auth
smtpd_sasl_security_options = noplaintext,noanonymous
smtpd_sasl_tls_security_options = noanonymous
smtpd_tls_CAfile = /etc/ssl/cert.pem
smtpd_tls_cert_file = /usr/local/etc/letsencrypt/live/home.utahime.org/fullchain.pem
smtpd_tls_ciphers = high
smtpd_tls_key_file = /usr/local/etc/letsencrypt/live/home.utahime.org/privkey.pem
smtpd_tls_loglevel = 1
smtpd_tls_mandatory_ciphers = high
smtpd_tls_mandatory_protocols = !SSLv2 !SSLv3 !TLSv1 !TLSv1.1
smtpd_tls_protocols = !SSLv2 !SSLv3 !TLSv1 !TLSv1.1
smtpd_tls_received_header = yes
smtpd_tls_security_level = may
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_ssl_cache

--master.cf--
smtp      inet  n       -       n       -       -       smtpd
submission inet n      -       n       -       -       smtpd
        -o smtpd_etrn_restrictions=reject
        -o smtpd_relay_restrictions=permit_sasl_authenticated,reject
        -o smtpd_sasl_auth_enable=yes
        -o smtpd_tls_security_level=encrypt
        -o syslog_name=postfix/submission
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
relay     unix  -       -       n       -       -       smtp
        -o syslog_name=postfix/$service_name
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

-- end of postfinger output --

---
Yasuhiro KIMURA
Reply | Threaded
Open this post in threaded view
|

Re: Postfix 3.5.5 and TLS handshake failure

Viktor Dukhovni
In reply to this post by Christos Chatzaras
On Sun, Jul 26, 2020 at 02:21:25PM +0300, Christos Chatzaras wrote:

> Few hours ago I upgrade from Postfix 3.5.4 to 3.5.5 and sometimes I get "Cannot start TLS: handshake failure":
>
> ------
> Jul 26 13:21:10 smtp2 postfix/smtpd[26600]: 1DB241F4EA: client=server28.example.net[138.201.82.xxx]
> Jul 26 13:21:10 smtp2 postfix/cleanup[26147]: 1DB241F4EA: message-id=<[hidden email]>
> Jul 26 13:21:10 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
> Jul 26 13:21:10 smtp2 relay2/smtp[26609]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=0.42, delays=0.4/0/0.02/0, dsn=4.7.5, status=deferred (Cannot start TLS: handshake failure)
> Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: from=<[hidden email]>, size=5509, nrcpt=1 (queue active)
> Jul 26 13:26:50 smtp2 relay4/smtp[26535]: 1DB241F4EA: to=<[hidden email]>, relay=mail.example.org[138.201.51.72]:25, delay=341, delays=340/0/0.04/0.53, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
> as 6F1B02869AA)
> Jul 26 13:26:50 smtp2 postfix/qmgr[1637]: 1DB241F4EA: removed
> ------
>
> These messages are delivered the next time the sender SMTP tries to deliver the message.

The server at 138.201.51.72 exhibits intermittent handshake failures, it
emits an incorrectly encoded certificate ~50% of the time.  Perhaps
there's a load-balancer there, or some on-path network device sometimes
garbles packets.

> Also I use Monit to monitor Postfix and after the upgrade to 3.5.5 version I get messages like this:
>
> ------
> Connection failed Service postfix
>  Date: Sun, 26 Jul 2020 14:01:39
>  Action: restart
>  Host: server28.example.com
>  Description: failed protocol test [SMTP] at [127.0.0.1]:25 [TCP/IP] -- Error receiving data from the mailserver -- Resource temporarily unavailable
> ------

The SMTP server issue is real, patch shortly.

--
    Viktor.