From owner-freebsd-questions@freebsd.org Sun Jun 21 21:34:32 2020 Return-Path: Delivered-To: freebsd-questions@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 8E83A335325 for ; Sun, 21 Jun 2020 21:34:32 +0000 (UTC) (envelope-from jmc-freebsd2@milibyte.co.uk) Received: from p3plwbeout24-04.prod.phx3.secureserver.net (p3plsmtp24-04-2.prod.phx3.secureserver.net [68.178.252.188]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "wbeout.secureserver.net", Issuer "Starfield Secure Certificate Authority - G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 49qm5g2J3Mz3RdK for ; Sun, 21 Jun 2020 21:34:30 +0000 (UTC) (envelope-from jmc-freebsd2@milibyte.co.uk) Received: from outmx-028.london.gridhost.co.uk ([95.142.156.253]) by :WBEOUT: with ESMTP id n7bAj1tDm3zmCn7bBj1AmO; Sun, 21 Jun 2020 14:33:57 -0700 X-CMAE-Analysis: v=2.3 cv=B5XHL9lM c=1 sm=1 tr=0 a=0sP6G7xXiiOFqQt3g3kR8w==:117 a=aH6JTgnnTGHwN2iBTwNb8w==:17 a=nTHF0DUjJn0A:10 a=r77TgQKjGQsHNAKrUKIA:9 a=4-FpMA6rAAAA:8 a=D7rCoLxHAAAA:8 a=pGLkceISAAAA:8 a=62ntRvTiAAAA:8 a=A1K3qvR8KmT1ZCZBAZIA:9 a=ihyjpYIc2HIF6waE:21 a=CfIkkmiYvtF7bQw6:21 a=QEXdDO2ut3YA:10 a=JCfAD3jrePcA:10 a=ZMy_opFM1gdiYSvxJuUA:9 a=sxefmXyn4opdbiNc:21 a=yt0oIrVYm6VN5AHW:21 a=fJhMza_Kl4qR9rbP:21 a=_W_S_7VecoQA:10 a=oUcH5ZleDwtbiW4PWyS7:22 a=P3xHhOtoK6rroZ9zpUER:22 a=pToNdpNmrtiFLRE6bQ9Z:22 X-SECURESERVER-ACCT: X-SID: n7bAj1tDm3zmC Received: from curlew.milibyte.co.uk (unknown [82.71.56.121]) (Authenticated sender: mailpool@milibyte.co.uk) by outmx-028.london.gridhost.co.uk (Postfix) with ESMTPA id EE034221B18C1 for ; Sun, 21 Jun 2020 22:33:55 +0100 (BST) Received: from [127.0.0.1] (helo=curlew.localnet) by curlew.milibyte.co.uk with esmtp (Exim 4.93.0.4) (envelope-from ) id 1jn7b2-0001TT-5p for freebsd-questions@freebsd.org; Sun, 21 Jun 2020 22:33:48 +0100 From: Mike Clarke To: freebsd-questions@freebsd.org Subject: Re: Exim - retry time not reached for any host Date: Sun, 21 Jun 2020 22:33:48 +0100 Message-ID: <1954651.YXp4yczo3S@curlew> In-Reply-To: <40ca3e9d-2859-6428-e7ad-c1b2dff36a69@smokepit.net> References: <2534646.NQNxk83B2J@curlew> <40ca3e9d-2859-6428-e7ad-c1b2dff36a69@smokepit.net> MIME-Version: 1.0 X-TSO-Authenticated: X-SA-Exim-Connect-IP: 127.0.0.1 X-SA-Exim-Mail-From: jmc-freebsd2@milibyte.co.uk X-SA-Exim-Scanned: No (on curlew.milibyte.co.uk); SAEximRunCond expanded to false X-CMAE-Envelope: MS4wfGTpmmzIGGjEY9eNovaug3D2SCt/Ip9PtoTqhI+silgtdDY4jUywTOQAZyAdk/h0KXIauOTX80woUz0vWX1ufJn2HHE6DJpFiGnzj+Jkv20F+TSYIYfg mxytya1TjS81yGFmtTKno0dGBAA9YtpIjDXND/tE8Ru297LjD1TjgNxsIIqGG/0UmAkK8p9qs+H5v17QwOZU+iilqU2keCTArKfbfFLMsFzgMinMrf+R58EZ X-Rspamd-Queue-Id: 49qm5g2J3Mz3RdK X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org; dkim=none; dmarc=none; spf=pass (mx1.freebsd.org: domain of jmc-freebsd2@milibyte.co.uk designates 68.178.252.188 as permitted sender) smtp.mailfrom=jmc-freebsd2@milibyte.co.uk X-Spamd-Result: default: False [-2.07 / 15.00]; RCVD_VIA_SMTP_AUTH(0.00)[]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-0.99)[-0.988]; FROM_HAS_DN(0.00)[]; RWL_MAILSPIKE_GOOD(0.00)[68.178.252.188:from]; TO_MATCH_ENVRCPT_ALL(0.00)[]; R_SPF_ALLOW(-0.20)[+ip4:68.178.252.0/24]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-questions@freebsd.org]; TO_DN_NONE(0.00)[]; RCPT_COUNT_ONE(0.00)[1]; NEURAL_HAM_LONG(-0.98)[-0.982]; RCVD_COUNT_THREE(0.00)[4]; MID_RHS_NOT_FQDN(0.50)[]; NEURAL_HAM_SHORT(-0.80)[-0.800]; RCVD_IN_DNSWL_NONE(0.00)[68.178.252.188:from]; DMARC_NA(0.00)[milibyte.co.uk]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; MIME_TRACE(0.00)[0:+,1:+,2:~]; ASN(0.00)[asn:26496, ipnet:68.178.252.0/22, country:US]; RCVD_TLS_LAST(0.00)[]; CTE_CASE(0.50)[] Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 7Bit X-Content-Filtered-By: Mailman/MimeDel 2.1.33 X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.33 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 21 Jun 2020 21:34:32 -0000 On Saturday, 20 June 2020 01:07:04 BST Daniel Lysfjord via freebsd-questions wrote: > On 19.06.2020 17:57, Mike Clarke wrote: > [..] > > > So it looks very much like the problem lies somewhere in my system even > > though there's been no changes made recently. I'd appreciate suggestions > > on how I should go about tracing and fixing the cause of this problem. > > Have you tried to start exim with "-bd -d+all" to get some debug output? OK, I've done that now and it's highlighted what's happening, though I'm not sure if it helps to explain why; To summarise it looks like the SSL connection fails but eventually succeeds after a number of retries although the delay could be an hour or more. As a workaround I've reverted exim from 4.94 to 4.93.0.4 which does not appear to suffer from this problem. And now for the details: 16:50:53 3161 Connecting to mail.gridhost.co.uk [95.142.156.28]:465 ... 95.142.156.28 in hosts_try_fastopen? yes (matched "*")^M 16:50:53 3161 TFO mode connection attempt to 95.142.156.28, 0 data^M 16:50:53 3161 connected^M 16:50:53 3161 ?considering: $primary_hostname^M 16:50:53 3161 ???expanding: $primary_hostname^M 16:50:53 3161 ??????result: curlew.milibyte.co.uk^M 16:50:53 3161 95.142.156.28 in hosts_avoid_esmtp? no (option unset)^M 16:50:53 3161 95.142.156.28 in hosts_require_ocsp? no (option unset)^M 16:50:53 3161 95.142.156.28 in hosts_request_ocsp? yes (matched "*")^M 16:50:53 3161 setting SSL CTX options: 0x42004000^M 16:50:53 3161 Diffie-Hellman initialized from default with 2048-bit prime^M 16:50:53 3161 Initialized TLS^M 16:50:53 3161 95.142.156.28 in tls_verify_hosts? no (option unset)^M 16:50:53 3161 95.142.156.28 in tls_try_verify_hosts? yes (matched "*")^M 16:50:53 3161 tls_verify_certificates: system^M 16:50:53 3161 95.142.156.28 in tls_verify_cert_hostnames? yes (matched "*")^M 16:50:53 3161 Cert hostname to check: "mail.gridhost.co.uk"^M 16:50:53 3161 Calling SSL_connect^M 16:50:53 3161 SSL_connect: before SSL initialization^M 16:50:53 3161 SSL_connect: error in SSLv3/TLS write client hello^M 16:50:53 3161 TLS error '(SSL_connect): error:00000000:lib(0):func(0):reason(0)'^M 16:50:53 3161 TLS session fail: (SSL_connect): error:00000000:lib(0):func(0):reason(0)^M 16:50:53 3161 SMTP(close)>>^M 16:50:53 3161 set_process_info: 3161 delivering 1jn2FA-0000ow-Uy: just tried mail.gridhost.co.uk [95.142.156.28]:465 for REDACTED@gmail.com: result DEFER^M 16:50:53 3161 added retry item for T:mail.gridhost.co.uk:95.142.156.28:465: errno=-37 more_errno=0,A flags=2^M This was repeated for the other 3 IP addresses for mail.gridhost.co.uk Then followed periodic attempts to deliver: 17:10:45 3445 Connecting to mail.gridhost.co.uk [95.142.156.8]:465 ... 95.142.156.8 in hosts_try_fastopen? yes (matched "*")^M 17:10:45 3445 SSL_connect: error in SSLv3/TLS write client hello^M 17:30:45 3493 Connecting to mail.gridhost.co.uk [95.142.156.8]:465 ... 95.142.156.8 in hosts_try_fastopen? yes (matched "*")^M 17:30:45 3493 SSL_connect: error in SSLv3/TLS write client hello^M And eventual success after 1 hour and 20 minutes 18:10:45 3840 Connecting to mail.gridhost.co.uk [95.142.156.18]:465 ... 95.142.156.18 in hosts_try_fastopen? yes (matched "*")^M 18:10:45 3840 TFO mode connection attempt to 95.142.156.18, 0 data^M 18:10:45 3840 connected^M 18:10:45 3840 ?considering: $primary_hostname^M 18:10:45 3840 ???expanding: $primary_hostname^M 18:10:45 3840 ??????result: curlew.milibyte.co.uk^M 18:10:45 3840 95.142.156.18 in hosts_avoid_esmtp? no (option unset)^M 18:10:45 3840 95.142.156.18 in hosts_require_ocsp? no (option unset)^M 18:10:45 3840 95.142.156.18 in hosts_request_ocsp? yes (matched "*")^M 18:10:45 3840 setting SSL CTX options: 0x42004000^M 18:10:45 3840 Diffie-Hellman initialized from default with 2048-bit prime^M 18:10:45 3840 Initialized TLS^M 18:10:45 3840 95.142.156.18 in tls_verify_hosts? no (option unset)^M 18:10:45 3840 95.142.156.18 in tls_try_verify_hosts? yes (matched "*")^M 18:10:45 3840 tls_verify_certificates: system^M 18:10:45 3840 95.142.156.18 in tls_verify_cert_hostnames? yes (matched "*")^M 18:10:45 3840 Cert hostname to check: "mail.gridhost.co.uk"^M 18:10:45 3840 Calling SSL_connect^M 18:10:45 3840 SSL_connect: before SSL initialization^M 18:10:45 3840 SSL_connect: SSLv3/TLS write client hello^M 18:10:45 3840 SSL_connect: SSLv3/TLS write client hello^M 18:10:45 3840 SSL_connect: SSLv3/TLS read server hello^M 18:10:45 3840 SSL verify ok: depth=2 SN=/C=US/O=SecureTrust Corporation/CN=SecureTrust CA^M 18:10:45 3840 SSL verify ok: depth=1 SN=/C=US/ST=Illinois/L=Chicago/O=Trustwave Holdings, Inc./CN=Trustwave Organization Validation SHA256 CA , Level 1/emailAddress=ca@trustwave.com^M 18:10:45 3840 SSL authenticated verify ok: depth=0 SN=/CN=*.gridhost.co.uk/O=Paragon Internet Group Limited/L=Hayes/ST=England/C=GB^M ... snip ... 18:10:45 3840 SMTP<< 250 2.0.0 Ok: queued as 6BB47221B18C1^M Previous tests have followed a similar pattern but with different times before successful delivery. Exim was upgraded from 4.93.0.4 to 4.94 a few weeks ago so it's possible this might have been happening since then. I don't often look at the exim log so wouldn't have noticed the long delays in sending emails. As an experiment I reverted to 4.93.0.4 and performed more tests with all emails being successfully delivered on the first attempt. This now leaves the question as to whether this is a new bug in 4.94 or if there's some less than ideal setting in my configuration which I've managed to get away with over the last few years but is causing a problem with the new version. In case it's relevant here's what I expect to be the appropriate snippets from my exim configuration: milibyte_route: driver = manualroute domains = !+local_domains transport = remote_auth_smtp condition = ${if match_domain{${domain:$h_From:}}{milibyte.co.uk}{yes}{no}} route_list = * mail3.gridhost.co.uk no_more remote_auth_smtp: driver = smtp protocol = smtps hosts_require_auth = $host_address hosts_require_tls = $host_address