Fix callouts connection fallback from TLS to cleartext. Bug 1897

19 files changed, 156 insertions, 20 deletions

diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog
index 52e04926f..80ea2105d 100644
--- a/doc/doc-txt/ChangeLog
+++ b/doc/doc-txt/ChangeLog
@@ -112,6 +112,8 @@ JH/29 Fix the connection_reject log selector to apply to the connect ACL.
       Previously it only applied to the main-section connection policy
       options.
 
+JH/30 Bug 1897: fix callouts connection fallback from TLS to cleartext.
+
 
 Exim version 4.87
 -----------------
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index ecdb8bf26..f506a75d6 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -1948,12 +1948,9 @@ if (  smtp_peer_options & PEER_OFFERED_TLS
     if (rc != OK)
       {
 # ifdef EXPERIMENTAL_DANE
-      if (rc == DEFER && lflags.dane)
-	{
-	log_write(0, LOG_MAIN,
+      if (lflags.dane) log_write(0, LOG_MAIN,
 	  "DANE attempt failed; no TLS connection to %s [%s]",
 	  host->name, host->address);
-	}
 # endif
 
       save_errno = ERRNO_TLSFAILURE;
diff --git a/src/src/verify.c b/src/src/verify.c
index 1ff8cd17f..11f1e10eb 100644
--- a/src/src/verify.c
+++ b/src/src/verify.c
@@ -617,6 +617,7 @@ can do it there for the non-rcpt-verify case.  For this we keep an addresscount.
 		  addr->transport);
     if (inblock.sock < 0)
       {
+      HDEBUG(D_verify) debug_printf("connect: %s\n", strerror(errno));
       addr->message = string_sprintf("could not connect to %s [%s]: %s",
           host->name, host->address, strerror(errno));
       transport_name = NULL;
@@ -820,24 +821,22 @@ can do it there for the non-rcpt-verify case.  For this we keep an addresscount.
 	connection, if the options permit it for this host. */
         if (rc != OK)
           {
-	  if (rc == DEFER)
-	    {
-	    (void)close(inblock.sock);
+	  HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
+	  (void)close(inblock.sock);
 # ifndef DISABLE_EVENT
-	    (void) event_raise(addr->transport->event_action,
-				    US"tcp:close", NULL);
+	  (void) event_raise(addr->transport->event_action,
+				  US"tcp:close", NULL);
 # endif
-	    if (  ob->tls_tempfail_tryclear
-	       && !smtps
-	       && verify_check_given_host(&ob->hosts_require_tls, host) != OK
-	       )
-	      {
-	      log_write(0, LOG_MAIN, "TLS session failure:"
-		" delivering unencrypted to %s [%s] (not in hosts_require_tls)",
-		host->name, host->address);
-	      suppress_tls = TRUE;
-	      goto tls_retry_connection;
-	      }
+	  if (  ob->tls_tempfail_tryclear
+	     && !smtps
+	     && verify_check_given_host(&ob->hosts_require_tls, host) != OK
+	     )
+	    {
+	    log_write(0, LOG_MAIN, "TLS session failure:"
+	      " callout unencrypted to %s [%s] (not in hosts_require_tls)",
+	      host->name, host->address);
+	    suppress_tls = TRUE;
+	    goto tls_retry_connection;
 	    }
 
 	  /*save_errno = ERRNO_TLSFAILURE;*/
@@ -1093,6 +1092,7 @@ can do it there for the non-rcpt-verify case.  For this we keep an addresscount.
 #ifdef SUPPORT_TLS
 	    tls_close(FALSE, TRUE);
 #endif
+	    HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
 	    (void)close(inblock.sock);
 #ifndef DISABLE_EVENT
 	    (void) event_raise(addr->transport->event_action,
@@ -1305,6 +1305,7 @@ can do it there for the non-rcpt-verify case.  For this we keep an addresscount.
 #ifdef SUPPORT_TLS
       tls_close(FALSE, TRUE);
 #endif
+      HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
       (void)close(inblock.sock);
 #ifndef DISABLE_EVENT
       (void) event_raise(addr->transport->event_action, US"tcp:close", NULL);
@@ -1626,6 +1627,7 @@ if(cutthrough.fd >= 0)
   #ifdef SUPPORT_TLS
   tls_close(FALSE, TRUE);
   #endif
+  HDEBUG(D_transport|D_acl|D_v) debug_printf("  SMTP(close)>>\n");
   (void)close(cutthrough.fd);
   cutthrough.fd = -1;
   HDEBUG(D_acl) debug_printf("----------- cutthrough shutdown (%s) ------------\n", why);
diff --git a/test/confs/2051 b/test/confs/2051
new file mode 120000
index 000000000..cde0a73c4
--- /dev/null
+++ b/test/confs/2051
@@ -0,0 +1 @@
+2151
\ No newline at end of file
diff --git a/test/confs/2151 b/test/confs/2151
new file mode 100644
index 000000000..f64cdd50e
--- /dev/null
+++ b/test/confs/2151
@@ -0,0 +1,43 @@
+# Exim test configuration 2151
+
+.include DIR/aux-var/tls_conf_prefix
+
+
+# ----- Main settings -----
+
+acl_smtp_rcpt = acl_rcpt
+callout_random_local_part = $primary_hostname--testing
+trusted_users = CALLER
+
+tls_advertise_hosts = 127.0.0.1 : HOSTIPV4
+
+tls_certificate = DIR/aux-fixed/exim-ca/example.com/server1.example.com/server1.example.com.pem
+tls_privatekey = DIR/aux-fixed/exim-ca/example.com/server1.example.com/server1.example.com.unlocked.key
+
+# ----- ACL -----
+
+begin acl
+
+acl_rcpt:
+  accept   verify  = recipient/callout=1s,use_sender
+
+# ----- Routers -----
+
+begin routers
+
+callout:
+  driver = manualroute
+  transport = smtp
+  route_data = 127.0.0.1
+  self = send
+
+
+# ----- Transports -----
+
+begin transports
+
+smtp:
+  driver = smtp
+  port = PORT_S
+
+# End
diff --git a/test/log/2051 b/test/log/2051
new file mode 100644
index 000000000..baa775c0d
--- /dev/null
+++ b/test/log/2051
@@ -0,0 +1,3 @@
+1999-03-02 09:44:33 H=127.0.0.1 [127.0.0.1] TLS error on connection (gnutls_handshake): timed out
+1999-03-02 09:44:33 TLS session failure: callout unencrypted to 127.0.0.1 [127.0.0.1] (not in hosts_require_tls)
+1999-03-02 09:44:33 10HmaX-0005vi-00 <= s1@test.ex U=CALLER P=local-esmtp S=sss
diff --git a/test/log/2151 b/test/log/2151
new file mode 100644
index 000000000..c2cc11363
--- /dev/null
+++ b/test/log/2151
@@ -0,0 +1,3 @@
+1999-03-02 09:44:33 H=127.0.0.1 [127.0.0.1] TLS error on connection (SSL_connect): timed out
+1999-03-02 09:44:33 TLS session failure: callout unencrypted to 127.0.0.1 [127.0.0.1] (not in hosts_require_tls)
+1999-03-02 09:44:33 10HmaX-0005vi-00 <= s1@test.ex U=CALLER P=local-esmtp S=sss
diff --git a/test/scripts/2000-GnuTLS/2051 b/test/scripts/2000-GnuTLS/2051
new file mode 120000
index 000000000..ac5066b61
--- /dev/null
+++ b/test/scripts/2000-GnuTLS/2051
@@ -0,0 +1 @@
+../2100-OpenSSL/2151
\ No newline at end of file
diff --git a/test/scripts/2100-OpenSSL/2151 b/test/scripts/2100-OpenSSL/2151
new file mode 100644
index 000000000..19dfc6479
--- /dev/null
+++ b/test/scripts/2100-OpenSSL/2151
@@ -0,0 +1,34 @@
+# TLS client: recipient callout - TLS fail, retry in clear
+need_ipv4
+#
+server PORT_S 2
+220 Server ready
+EHLO
+250-wotcher mate
+250-STARTTLS
+250 OK
+STARTTLS
+250
+.
+220 Server ready
+EHLO
+250-wotcher mate
+250-STARTTLS
+250 OK
+MAIL FROM
+250 OK
+RCPT TO
+250 OK
+QUIT
+250 OK
+****
+exim -odq -bs
+ehlo xxxx
+mail from: s1@test.ex
+rcpt to: r1@test.ex
+data
+.
+quit
+****
+no_stdout_check
+no_msglog_check
diff --git a/test/stderr/0227 b/test/stderr/0227
index 7a75ec015..e07b2ba55 100644
--- a/test/stderr/0227
+++ b/test/stderr/0227
@@ -9,6 +9,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<ok@localhost>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: smtp_connection MAIN
   SMTP connection from root closed by QUIT
 LOG: smtp_connection MAIN
@@ -26,6 +27,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<bad@localhost>
   SMTP<< 550 Unknown user
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify fail for <bad@localhost>: response to "RCPT TO:<bad@localhost>" from 127.0.0.1 [127.0.0.1] was: 550 Unknown user
 LOG: MAIN REJECT
@@ -43,6 +45,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<uncheckable@localhost1>
   SMTP<< 450 Temporary error
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify defer for <uncheckable@localhost1>: response to "RCPT TO:<uncheckable@localhost1>" from 127.0.0.1 [127.0.0.1] was: 450 Temporary error
 LOG: MAIN REJECT
@@ -58,6 +61,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP<< 550 Error for <>
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify fail for <uncheckable2@localhost1>: response to "MAIL FROM:<>" from 127.0.0.1 [127.0.0.1] was: 550 Error for <>
 LOG: MAIN REJECT
@@ -74,6 +78,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP<< 550-Multiline error for <>
          550 Here's the second line
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify fail for <uncheckable@localhost1>: response to "MAIL FROM:<>" from 127.0.0.1 [127.0.0.1] was: 550-Multiline error for <>\n550 Here's the second line
 LOG: MAIN REJECT
@@ -91,6 +96,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<z@remote.domain>
   SMTP<< 550 Recipient not liked
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.3] U=root F=<uncheckable@localhost1> rejected RCPT <z@remote.domain>: response to "RCPT TO:<z@remote.domain>" from 127.0.0.1 [127.0.0.1] was: 550 Recipient not liked
 LOG: smtp_connection MAIN
@@ -107,6 +113,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP<< 550-Recipient not liked on two lines
          550 Here's the second
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.3] U=root F=<uncheckable@localhost1> rejected RCPT <z@remote.domain>: response to "RCPT TO:<z@remote.domain>" from 127.0.0.1 [127.0.0.1] was: 550-Recipient not liked on two lines\n550 Here's the second
 LOG: smtp_connection MAIN
@@ -130,6 +137,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<abcd@x.y.z>
   SMTP<< 550 Not liked
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.4] U=root F=<uncheckable@localhost1> rejected after DATA: there is no valid sender in any header line
 LOG: smtp_connection MAIN
@@ -145,6 +153,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<abcd@x.y.z>
   SMTP<< 550 Not liked
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.4] U=root F=<uncheckable@localhost1> rejected after DATA: there is no valid sender in any header line
 LOG: smtp_connection MAIN
@@ -167,6 +176,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@localhost1>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.5] U=root F=<ok@localhost1> rejected RCPT <z@remote.domain>: relay not permitted
 LOG: smtp_connection MAIN
@@ -189,6 +199,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@localhost1>
   SMTP<< 550 Don't like postmaster
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.5] U=root sender verify fail for <ok@localhost1>: response to "RCPT TO:<postmaster@localhost1>" from 127.0.0.1 [127.0.0.1] was: 550 Don't like postmaster
 LOG: MAIN REJECT
@@ -206,6 +217,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<z@remote.lmtp>
   SMTP<< 550 Recipient not liked
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.3] U=root F=<uncheckable@localhost1> rejected RCPT <z@remote.lmtp>: response to "RCPT TO:<z@remote.lmtp>" from 127.0.0.1 [127.0.0.1] was: 550 Recipient not liked
 LOG: smtp_connection MAIN
@@ -214,6 +226,7 @@ LOG: smtp_connection MAIN
   SMTP connection from root
 Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> QUIT
+  SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify defer for <bad@localhost1>: response to "initial connection" from 127.0.0.1 [127.0.0.1] was: connection dropped
 LOG: MAIN REJECT
diff --git a/test/stderr/0376 b/test/stderr/0376
index 664e248e2..dd58a1360 100644
--- a/test/stderr/0376
+++ b/test/stderr/0376
@@ -21,6 +21,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<ok@localhost>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for localhost:
   result=1 postmaster=0 random=0
 wrote positive callout cache address record for ok@localhost
@@ -59,6 +60,7 @@ callout cache: found domain record for localhost
 callout cache: address record expired for ok@localhost
 interface=NULL port=1224
 Connecting to 127.0.0.1 [127.0.0.1]:1224 ... failed: Connection refused
+connect: Connection refused
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify defer for <ok@localhost>: could not connect to 127.0.0.1 [127.0.0.1]: Connection refused
 created log directory TESTSUITE/spool/log
@@ -90,6 +92,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<bad@localhost>
   SMTP<< 550 REJECTED
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for localhost:
   result=1 postmaster=0 random=0
 wrote negative callout cache address record for bad@localhost
@@ -142,6 +145,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP<< 550 REJECT MAIL FROM
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for localhost:
   result=3 postmaster=0 random=0
 LOG: MAIN REJECT
@@ -201,6 +205,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@otherhost>
   SMTP<< 550 NOT OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost:
   result=1 postmaster=2 random=0
 wrote positive callout cache address record for ok@otherhost
@@ -261,6 +266,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@otherhost2>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost2:
   result=1 postmaster=1 random=0
 wrote positive callout cache address record for ok@otherhost2
@@ -308,6 +314,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<myhost.test.ex-dddddddd-testing@otherhost3>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost3:
   result=1 postmaster=0 random=1
 LOG: smtp_connection MAIN
@@ -352,6 +359,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<myhost.test.ex-dddddddd-testing@otherhost4>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost4:
   result=1 postmaster=0 random=1
 LOG: smtp_connection MAIN
@@ -409,6 +417,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@otherhost41>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost41:
   result=1 postmaster=1 random=2
 wrote positive callout cache address record for ok@otherhost41
@@ -464,6 +473,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@otherhost21>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost21:
   result=1 postmaster=1 random=0
 wrote positive callout cache address record for ok@otherhost21
@@ -494,6 +504,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<ok2@otherhost21>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost21:
   result=1 postmaster=1 random=0
 wrote positive callout cache address record for ok2@otherhost21
@@ -529,6 +540,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<ok@otherhost31>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost31:
   result=1 postmaster=0 random=2
 wrote positive callout cache address record for ok@otherhost31
@@ -559,6 +571,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<okok@otherhost31>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost31:
   result=1 postmaster=0 random=2
 wrote positive callout cache address record for okok@otherhost31
@@ -594,6 +607,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<okokok@otherhost31>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost31:
   result=1 postmaster=0 random=2
 wrote positive callout cache address record for okokok@otherhost31
@@ -622,6 +636,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP<< 250 OK
   SMTP>> RCPT TO:<myhost.test.ex-dddddddd-testing@otherhost51>
 SMTP timeout
+  SMTP(close)>>
 wrote callout cache domain record for otherhost51:
   result=1 postmaster=0 random=0
 LOG: MAIN REJECT
@@ -661,6 +676,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@otherhost52>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost52:
   result=1 postmaster=1 random=0
 wrote positive callout cache address record for okokok@otherhost52
@@ -691,6 +707,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<abcd@x.y.z>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for x.y.z:
   result=1 postmaster=0 random=0
 wrote positive callout cache address record for abcd@x.y.z/<somesender@a.domain>
@@ -722,6 +739,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP<< 250 OK
   SMTP>> RCPT TO:<abcd@x.y.z>
 SMTP timeout
+  SMTP(close)>>
 wrote callout cache domain record for x.y.z:
   result=1 postmaster=0 random=0
 LOG: MAIN
@@ -761,6 +779,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for otherhost9:
   result=1 postmaster=1 random=0
 wrote positive callout cache address record for ok@otherhost9
@@ -803,6 +822,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@test.ex>
   SMTP<< 250 OK
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for test.ex:
   result=1 postmaster=1 random=2
 wrote positive callout cache address record for z@test.ex/<postmaster@myhost.test.ex>
diff --git a/test/stderr/0398 b/test/stderr/0398
index 3825d7e86..3e3994b99 100644
--- a/test/stderr/0398
+++ b/test/stderr/0398
@@ -144,6 +144,7 @@ cmd buf flush ddd bytes
   SMTP<< 550 Unknown
   SMTP>> QUIT
 cmd buf flush ddd bytes
+  SMTP(close)>>
 locking TESTSUITE/spool/db/callout.lockfile
 locked  TESTSUITE/spool/db/callout.lockfile
 EXIM_DBOPEN(TESTSUITE/spool/db/callout)
diff --git a/test/stderr/0432 b/test/stderr/0432
index 2e2a8c1ee..e97e917fe 100644
--- a/test/stderr/0432
+++ b/test/stderr/0432
@@ -105,6 +105,7 @@ cmd buf flush ddd bytes
   SMTP<< 250 OK
   SMTP>> QUIT
 cmd buf flush ddd bytes
+  SMTP(close)>>
 locking TESTSUITE/spool/db/callout.lockfile
 locked  TESTSUITE/spool/db/callout.lockfile
 EXIM_DBOPEN(TESTSUITE/spool/db/callout)
@@ -269,6 +270,7 @@ MUNGED: ::1 will be omitted in what follows
 >>>   SMTP<< 250 OK
 >>>   SMTP>> QUIT
 >>> cmd buf flush 6 bytes
+>>>   SMTP(close)>>
 >>> wrote callout cache domain record for b:
 >>>   result=1 postmaster=0 random=0
 >>> wrote positive callout cache address record for a@b
@@ -304,6 +306,7 @@ MUNGED: ::1 will be omitted in what follows
 >>>   SMTP>> EHLO myhost.test.ex
 >>> cmd buf flush 21 bytes
 >>> SMTP timeout
+>>>   SMTP(close)>>
 >>> ----------- end verify ------------
 >>> accept: condition test deferred in ACL "mail"
 LOG: H=[1.2.3.4] sender verify defer for <p1@q>: Could not complete sender verify callout
diff --git a/test/stderr/0462 b/test/stderr/0462
index f8cb9b7c6..20418933a 100644
--- a/test/stderr/0462
+++ b/test/stderr/0462
@@ -28,6 +28,7 @@ Cutthrough cancelled by presence of postmaster verify
   SMTP>> RCPT TO:<postmaster@localhost>
   SMTP<< 550 NO
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for localhost:
   result=1 postmaster=2 random=0
 wrote positive callout cache address record for Ok@localhost
@@ -70,6 +71,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<NOTok@elsewhere>
   SMTP<< 550 NO
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for elsewhere:
   result=1 postmaster=0 random=0
 wrote negative callout cache address record for NOTok@elsewhere
@@ -103,6 +105,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> RCPT TO:<NOTok2@elsewhere>
   SMTP<< 550 NO
   SMTP>> QUIT
+  SMTP(close)>>
 wrote callout cache domain record for elsewhere:
   result=1 postmaster=0 random=0
 wrote negative callout cache address record for NOTok2@elsewhere
diff --git a/test/stderr/0473 b/test/stderr/0473
index 3fd0cbb51..ed7bc5359 100644
--- a/test/stderr/0473
+++ b/test/stderr/0473
@@ -20,6 +20,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP<< 250 OK
   SMTP>> RCPT TO:<r11@two.test.ex>
 SMTP timeout
+  SMTP(close)>>
 wrote callout cache domain record for two.test.ex:
   result=1 postmaster=0 random=0
 LOG: MAIN REJECT
@@ -43,6 +44,7 @@ callout cache: no address record found for r11@two.test.ex
 interface=NULL port=1224
 Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
 SMTP timeout
+  SMTP(close)>>
 LOG: MAIN REJECT
   U=CALLER F=<x11@two.test.ex> temporarily rejected RCPT r11@two.test.ex: Could not complete recipient verify callout
 LOG: smtp_connection MAIN
diff --git a/test/stderr/5403 b/test/stderr/5403
index b91e254f3..dfb5a97e4 100644
--- a/test/stderr/5403
+++ b/test/stderr/5403
@@ -89,5 +89,6 @@ MUNGED: ::1 will be omitted in what follows
 >>> accept: condition test succeeded in ACL "ar"
 >>> end of ACL "ar": ACCEPT
 >>>   SMTP>> QUIT
+>>>   SMTP(close)>>
 >>> ----------- cutthrough shutdown (host-checking mode) ------------
 LOG: 10HmaY-0005vi-00 <= CALLER@myhost.test.ex H=(myhost.test.ex) [1.2.3.4] P=esmtp S=sss for verify@domain.com
diff --git a/test/stderr/5410 b/test/stderr/5410
index 73a8b3b2b..7916518b7 100644
--- a/test/stderr/5410
+++ b/test/stderr/5410
@@ -253,6 +253,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> userx@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] X=TLSv1:AES256-SHA:256 CV=no C="250 OK id=10HmaY-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
@@ -483,6 +484,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> usery@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmbA-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
@@ -713,6 +715,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> usery@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmbC-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
diff --git a/test/stderr/5420 b/test/stderr/5420
index 635f4246d..a12451575 100644
--- a/test/stderr/5420
+++ b/test/stderr/5420
@@ -252,6 +252,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> userx@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] X=TLS1.x:xxxxRSA_AES_256_CBC_SHAnnn:256 CV=no C="250 OK id=10HmaY-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
@@ -482,6 +483,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> usery@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmbA-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
@@ -712,6 +714,7 @@ considering: ${tod_full}
 LOG: MAIN
   >> usery@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1] C="250 OK id=10HmbC-0005vi-00"
   SMTP>> QUIT
+  SMTP(close)>>
 ----------- cutthrough shutdown (delivered) ------------
 LOG: MAIN
   <= CALLER@myhost.test.ex U=CALLER P=local-esmtp S=sss
diff --git a/test/stderr/5840 b/test/stderr/5840
index 08712d0d9..b4b035a29 100644
--- a/test/stderr/5840
+++ b/test/stderr/5840
@@ -57,6 +57,7 @@ MUNGED: ::1 will be omitted in what follows
 >>>   SMTP<< 250 Accepted
 >>>   SMTP>> QUIT
 >>> cmd buf flush 6 bytes
+>>>   SMTP(close)>>
 >>> wrote callout cache domain record for dane256ee.test.ex:
 >>>   result=1 postmaster=0 random=0
 >>> wrote positive callout cache address record for CALLER@dane256ee.test.ex