Testsuite: longer timing for OpenSSL resumption tests

7 files changed, 28 insertions, 43 deletions

diff --git a/src/src/tls-openssl.c b/src/src/tls-openssl.c
index 3b060cc9c..ae0986aac 100644
--- a/src/src/tls-openssl.c
+++ b/src/src/tls-openssl.c
@@ -155,6 +155,7 @@ change this guard and punt the issue for a while longer. */
 # endif
 #endif
 
+#define TESTSUITE_TICKET_LIFE 10	/* seconds */
 /*************************************************
 *        OpenSSL option parse                    *
 *************************************************/
@@ -2044,7 +2045,7 @@ if (exim_tk.name[0])
   exim_tk_old = exim_tk;
   }
 
-if (f.running_in_test_harness) ssl_session_timeout = 6;
+if (f.running_in_test_harness) ssl_session_timeout = TESTSUITE_TICKET_LIFE;
 
 DEBUG(D_tls) debug_printf("OpenSSL: %s STEK\n", exim_tk.name[0] ? "rotating" : "creating");
 if (RAND_bytes(exim_tk.aes_key, sizeof(exim_tk.aes_key)) <= 0) return;
@@ -3908,16 +3909,17 @@ if (tlsp->host_resumable)
 #ifdef EXIM_HAVE_SESSION_TICKET
 	  SSL_SESSION_get_ticket_lifetime_hint(ss);
 #else			/* Use, fairly arbitrilarily, what we as server would */
-	  f.running_in_test_harness ? 6 : ssl_session_timeout;
+	  f.running_in_test_harness ? TESTSUITE_TICKET_LIFE : ssl_session_timeout;
 #endif
-	if (lifetime + dt->time_stamp < time(NULL))
+	time_t now = time(NULL), expires = lifetime + dt->time_stamp;
+	if (expires < now)
 	  {
-	  DEBUG(D_tls) debug_printf("session expired\n");
+	  DEBUG(D_tls) debug_printf("session expired (by " TIME_T_FMT "s from %lus)\n", now - expires, lifetime);
 	  dbfn_delete(dbm_file, tlsp->resume_index);
 	  }
 	else if (SSL_set_session(ssl, ss))
 	  {
-	  DEBUG(D_tls) debug_printf("good session\n");
+	  DEBUG(D_tls) debug_printf("good session (" TIME_T_FMT "s left of %lus)\n", expires - now, lifetime);
 	  tlsp->resumption |= RESUME_CLIENT_SUGGESTED;
 	  tlsp->verify_override = dt->verify_override;
 	  tlsp->ocsp = dt->ocsp;
diff --git a/test/confs/5892 b/test/confs/5892
index 0aec9bfaf..15b09fcff 100644
--- a/test/confs/5892
+++ b/test/confs/5892
@@ -30,6 +30,7 @@ tls_certificate = CDIR/server1.example.com/server1.example.com.chain.pem
 tls_privatekey =  CDIR/server1.example.com/server1.example.com.unlocked.key
 
 tls_resumption_hosts = 127.0.0.1
+remote_max_parallel = 1
 
 
 # ------ ACL ------
@@ -70,7 +71,7 @@ begin routers
 client:
   driver =	accept
   condition =	${if eq {SERVER}{server}{no}{yes}}
-  transport =	send_to_server${if eq{$local_part}{abcd}{2}{1}}
+  transport =	send_to_server${if eq{$local_part}{hostnotresume}{2}{1}}
 
 server:
   driver = redirect
diff --git a/test/log/5892 b/test/log/5892
index ce8b0ea7d..b128749ae 100644
--- a/test/log/5892
+++ b/test/log/5892
@@ -8,7 +8,7 @@
 1999-03-02 09:44:33 10HmaX-0005vi-00 bits	256
 1999-03-02 09:44:33 10HmaX-0005vi-00 => getticket@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmaY-0005vi-00"
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
-1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for resume@test.ex abcd@test.ex xyz@test.ex
+1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for resume@test.ex hostnotresume@test.ex xyz@test.ex
 1999-03-02 09:44:33 10HmaZ-0005vi-00 tls_out_resumption session resumed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 our cert subject	
 1999-03-02 09:44:33 10HmaZ-0005vi-00 peer cert subject	CN=server1.example.com
@@ -16,6 +16,8 @@
 1999-03-02 09:44:33 10HmaZ-0005vi-00 peer dn	/CN=server1.example.com
 1999-03-02 09:44:33 10HmaZ-0005vi-00 cipher	TLS1.x:ke-RSA-AES256-SHAnnn:xxx
 1999-03-02 09:44:33 10HmaZ-0005vi-00 bits	256
+1999-03-02 09:44:33 10HmaZ-0005vi-00 => resume@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx* CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
+1999-03-02 09:44:33 10HmaZ-0005vi-00 -> xyz@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx* CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
 1999-03-02 09:44:33 10HmaZ-0005vi-00 tls_out_resumption not requested or offered
 1999-03-02 09:44:33 10HmaZ-0005vi-00 our cert subject	
 1999-03-02 09:44:33 10HmaZ-0005vi-00 peer cert subject	CN=server1.example.com
@@ -23,9 +25,7 @@
 1999-03-02 09:44:33 10HmaZ-0005vi-00 peer dn	/CN=server1.example.com
 1999-03-02 09:44:33 10HmaZ-0005vi-00 cipher	TLS1.x:ke-RSA-AES256-SHAnnn:xxx
 1999-03-02 09:44:33 10HmaZ-0005vi-00 bits	256
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => resume@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx* CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
-1999-03-02 09:44:33 10HmaZ-0005vi-00 -> xyz@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx* CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => abcd@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbB-0005vi-00"
+1999-03-02 09:44:33 10HmaZ-0005vi-00 => hostnotresume@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbB-0005vi-00"
 1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbC-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for renewal@test.ex
 1999-03-02 09:44:33 10HmbC-0005vi-00 tls_out_resumption session resumed
@@ -47,7 +47,7 @@
 1999-03-02 09:44:33 10HmbE-0005vi-00 bits	256
 1999-03-02 09:44:33 10HmbE-0005vi-00 => postrenewal@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx* CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbF-0005vi-00"
 1999-03-02 09:44:33 10HmbE-0005vi-00 Completed
-1999-03-02 09:44:33 10HmbG-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for timeout@test.ex
+1999-03-02 09:44:33 10HmbG-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for aftertimeout@test.ex
 1999-03-02 09:44:33 10HmbG-0005vi-00 tls_out_resumption client requested new ticket, server provided
 1999-03-02 09:44:33 10HmbG-0005vi-00 our cert subject	
 1999-03-02 09:44:33 10HmbG-0005vi-00 peer cert subject	CN=server1.example.com
@@ -55,7 +55,7 @@
 1999-03-02 09:44:33 10HmbG-0005vi-00 peer dn	/CN=server1.example.com
 1999-03-02 09:44:33 10HmbG-0005vi-00 cipher	TLS1.x:ke-RSA-AES256-SHAnnn:xxx
 1999-03-02 09:44:33 10HmbG-0005vi-00 bits	256
-1999-03-02 09:44:33 10HmbG-0005vi-00 => timeout@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbH-0005vi-00"
+1999-03-02 09:44:33 10HmbG-0005vi-00 => aftertimeout@test.ex R=client T=send_to_server1 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbH-0005vi-00"
 1999-03-02 09:44:33 10HmbG-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbI-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for notreq@test.ex
 1999-03-02 09:44:33 10HmbI-0005vi-00 tls_out_resumption not requested or offered
@@ -159,8 +159,8 @@
 1999-03-02 09:44:33 peer dn	
 1999-03-02 09:44:33 cipher	TLS1.x:ke-RSA-AES256-SHAnnn:xxx
 1999-03-02 09:44:33 bits	256
-1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@myhost.test.ex H=the.local.host.name (myhost.test.ex) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@myhost.test.ex for abcd@test.ex
-1999-03-02 09:44:33 10HmbB-0005vi-00 => :blackhole: <abcd@test.ex> R=server
+1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@myhost.test.ex H=the.local.host.name (myhost.test.ex) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@myhost.test.ex for hostnotresume@test.ex
+1999-03-02 09:44:33 10HmbB-0005vi-00 => :blackhole: <hostnotresume@test.ex> R=server
 1999-03-02 09:44:33 10HmbB-0005vi-00 Completed
 1999-03-02 09:44:33 tls_in_resumption	session resumed, also new ticket
 1999-03-02 09:44:33 our cert subject	CN=server1.example.com
@@ -189,8 +189,8 @@
 1999-03-02 09:44:33 peer dn	
 1999-03-02 09:44:33 cipher	TLS1.x:ke-RSA-AES256-SHAnnn:xxx
 1999-03-02 09:44:33 bits	256
-1999-03-02 09:44:33 10HmbH-0005vi-00 <= CALLER@myhost.test.ex H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbG-0005vi-00@myhost.test.ex for timeout@test.ex
-1999-03-02 09:44:33 10HmbH-0005vi-00 => :blackhole: <timeout@test.ex> R=server
+1999-03-02 09:44:33 10HmbH-0005vi-00 <= CALLER@myhost.test.ex H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbG-0005vi-00@myhost.test.ex for aftertimeout@test.ex
+1999-03-02 09:44:33 10HmbH-0005vi-00 => :blackhole: <aftertimeout@test.ex> R=server
 1999-03-02 09:44:33 10HmbH-0005vi-00 Completed
 1999-03-02 09:44:33 tls_in_resumption	no client request
 1999-03-02 09:44:33 our cert subject	CN=server1.example.com
diff --git a/test/scripts/5892-Resume-OpenSSL/5892 b/test/scripts/5892-Resume-OpenSSL/5892
index e09fc6398..77b93704b 100644
--- a/test/scripts/5892-Resume-OpenSSL/5892
+++ b/test/scripts/5892-Resume-OpenSSL/5892
@@ -4,21 +4,21 @@
 exim -DSERVER=server -DOPTION=+no_tlsv1_3 -bd -oX PORT_D
 ****
 exim -DVALUE=resume -odf getticket@test.ex
-Test message. Contains FF: ˙
+Test message.
 ****
-exim -DVALUE=resume -odf resume@test.ex abcd@test.ex xyz@test.ex
+exim -DVALUE=resume -odf resume@test.ex hostnotresume@test.ex xyz@test.ex
 Test message to two different hosts, one does not support resume
 ****
 # allow time for ticket to hit renewal time
-sleep 3
+sleep 5
 exim -DVALUE=resume -odf renewal@test.ex
 Test message.
 ****
 exim -DVALUE=resume -odf postrenewal@test.ex
 Test message.
 ****
-sleep 3
-exim -DVALUE=resume -odf timeout@test.ex
+sleep 5
+exim -DVALUE=resume -odf aftertimeout@test.ex
 Test message.
 ****
 exim -odf notreq@test.ex
diff --git a/test/scripts/5893-Resume-OpenSSL-OCSP/5893 b/test/scripts/5893-Resume-OpenSSL-OCSP/5893
index 2c525d838..2c103c788 100644
--- a/test/scripts/5893-Resume-OpenSSL-OCSP/5893
+++ b/test/scripts/5893-Resume-OpenSSL-OCSP/5893
@@ -10,14 +10,14 @@ exim -DVALUE=resume -odf resume@test.ex abcd@test.ex xyz@test.ex
 Test message to two different hosts, one does not support resume
 ****
 # allow time for ticket to hit renewal time
-sleep 3
+sleep 5
 exim -DVALUE=resume -odf renewal@test.ex
 Test message.
 ****
 exim -DVALUE=resume -odf postrenewal@test.ex
 Test message.
 ****
-sleep 3
+sleep 5
 exim -DVALUE=resume -odf timeout@test.ex
 Test message.
 ****
diff --git a/test/scripts/5895-Resume-OpenSSL-TLS1.3-OCSP/5895 b/test/scripts/5895-Resume-OpenSSL-TLS1.3-OCSP/5895
index 5709b4a78..e54803896 100644
--- a/test/scripts/5895-Resume-OpenSSL-TLS1.3-OCSP/5895
+++ b/test/scripts/5895-Resume-OpenSSL-TLS1.3-OCSP/5895
@@ -10,14 +10,14 @@ exim -DVALUE=resume -odf resume@test.ex abcd@test.ex xyz@test.ex
 Test message to two different hosts, one does not support resume
 ****
 # allow time for ticket to hit renewal time
-sleep 3
+sleep 5
 exim -DVALUE=resume -odf renewal@test.ex
 Test message.
 ****
 exim -DVALUE=resume -odf postrenewal@test.ex
 Test message.
 ****
-sleep 3
+sleep 5
 exim -DVALUE=resume -odf timeout@test.ex
 Test message.
 ****
diff --git a/test/stderr/5410 b/test/stderr/5410
index 7d0961733..8e65e3feb 100644
--- a/test/stderr/5410
+++ b/test/stderr/5410
@@ -16,15 +16,12 @@ LOG: smtp_connection MAIN
  ├considering: $tod_full
  ├──expanding: $smtp_active_hostname ESMTP Exim $version_number $tod_full
  ╰─────result: myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
- in limits_advertise_hosts?
- list element: !*
  in dsn_advertise_hosts? no (option unset)
  in pipelining_advertise_hosts?
  list element: *
   in pipelining_advertise_hosts? yes (matched "*")
  in chunking_advertise_hosts?
  in chunking_advertise_hosts? no (end of list)
- in tls_advertise_hosts?
  list element: *
   in tls_advertise_hosts? yes (matched "*")
  â•­considering: ${if eq {SERVER}{server}{queue}{cutthrough}}
@@ -121,9 +118,6 @@ cmd buf flush ddd bytes
   ├considering: }} {match{$item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: .outlook.com\$
   ╰─────result: .outlook.com$
- compiled RE '.outlook.com$' not found in local cache
- compiling RE '.outlook.com$'
- compiled RE '.outlook.com$' saved in local cache
   ╭───scanning: $item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├───scanning: }{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: $item
@@ -614,15 +608,12 @@ LOG: smtp_connection MAIN
  ├considering: $tod_full
  ├──expanding: $smtp_active_hostname ESMTP Exim $version_number $tod_full
  ╰─────result: myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
- in limits_advertise_hosts?
- list element: !*
  in dsn_advertise_hosts? no (option unset)
  in pipelining_advertise_hosts?
  list element: *
   in pipelining_advertise_hosts? yes (matched "*")
  in chunking_advertise_hosts?
  in chunking_advertise_hosts? no (end of list)
- in tls_advertise_hosts?
  list element: *
   in tls_advertise_hosts? yes (matched "*")
  â•­considering: ${if eq {SERVER}{server}{queue}{cutthrough}}
@@ -719,9 +710,6 @@ cmd buf flush ddd bytes
   ├considering: }} {match{$item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: .outlook.com\$
   ╰─────result: .outlook.com$
- compiled RE '.outlook.com$' not found in local cache
- compiling RE '.outlook.com$'
- compiled RE '.outlook.com$' saved in local cache
   ╭───scanning: $item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├───scanning: }{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: $item
@@ -1165,15 +1153,12 @@ LOG: smtp_connection MAIN
  ├considering: $tod_full
  ├──expanding: $smtp_active_hostname ESMTP Exim $version_number $tod_full
  ╰─────result: myhost.test.ex ESMTP Exim x.yz Tue, 2 Mar 1999 09:44:33 +0000
- in limits_advertise_hosts?
- list element: !*
  in dsn_advertise_hosts? no (option unset)
  in pipelining_advertise_hosts?
  list element: *
   in pipelining_advertise_hosts? yes (matched "*")
  in chunking_advertise_hosts?
  in chunking_advertise_hosts? no (end of list)
- in tls_advertise_hosts?
  list element: *
   in tls_advertise_hosts? yes (matched "*")
  â•­considering: ${if eq {SERVER}{server}{queue}{cutthrough}}
@@ -1270,9 +1255,6 @@ cmd buf flush ddd bytes
   ├considering: }} {match{$item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: .outlook.com\$
   ╰─────result: .outlook.com$
- compiled RE '.outlook.com$' not found in local cache
- compiling RE '.outlook.com$'
- compiled RE '.outlook.com$' saved in local cache
   ╭───scanning: $item}{\N^250-([\w.]+)\s\N}}} {$1}}
   ├───scanning: }{\N^250-([\w.]+)\s\N}}} {$1}}
   ├──expanding: $item