Exim - retry time not reached for any host

[Mike Clarke]

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 at 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 at 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