> On Jul 26, 2020, at 06:33, Christos Chatzaras <ch...@cretaforce.gr> 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=<f42ae274b54d32f368dd3897ee7c7...@www.example.com>
>> Jul 26 13:21:10 smtp2 postfix/qmgr[1637]: 1DB241F4EA:
>> from=<i...@example.com>, size=5509, nrcpt=1 (queue active)
>> Jul 26 13:21:10 smtp2 relay2/smtp[26609]: 1DB241F4EA: to=<i...@example.org>,
>> 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=<i...@example.com>, size=5509, nrcpt=1 (queue active)
>> Jul 26 13:26:50 smtp2 relay4/smtp[26535]: 1DB241F4EA: to=<i...@example.org>,
>> 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
