Debug: align tracing out for TFO connections with plain ones

diff --git a/src/src/smtp_out.c b/src/src/smtp_out.c
index d8cb42e01e11e8dd711d7aabe336551dba5d1c25..ea052b58a3a30355dc7a3201d2bfa2175e20e5d1 100644 (file)
--- a/src/src/smtp_out.c
+++ b/src/src/smtp_out.c
@@ -641,7 +641,7 @@ for (;;)
 
   if((rc = ip_recv(cctx, inblock->buffer, inblock->buffersize, timeout)) <= 0)
     {
-    DEBUG(D_deliver|D_transport|D_acl)
+    DEBUG(D_deliver|D_transport|D_acl|D_v)
       debug_printf_indent(errno ? "  SMTP(%s)<<\n" : "  SMTP(closed)<<\n",
        strerror(errno));
     break;

diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 6ce4c9ded56fbda4efaa6830e36d50626a90d4a1..94c1fe40cc7b0e8f26fa2062d520d1c3c6c43b9d 100644 (file)
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -590,10 +590,6 @@ switch(*errno_value)
        transport_count);
     return FALSE;
 
-  case ECONNREFUSED:           /* First-read error on a TFO conn */
-    if (verify_mode) *message = US strerror(*errno_value);
-    return FALSE;              /* nonverify, do not set message */
-
   case ERRNO_SMTPFORMAT:       /* Handle malformed SMTP response */
     s = string_printing(buffer);
     while (isspace(*s)) s++;
@@ -2844,6 +2840,29 @@ return OK;
   int code;
 
   RESPONSE_FAILED:
+    if (errno == ECONNREFUSED) /* first-read error on a TFO conn */
+      {
+      /* There is a testing facility for simulating a connection timeout, as I
+      can't think of any other way of doing this. It converts a connection
+      refused into a timeout if the timeout is set to 999999.  This is done for
+      a 3whs connection in ip_connect(), but a TFO connection does not error
+      there - instead it gets ECONNREFUSED on the first data read.  Tracking
+      that a TFO really was done is too hard, or we would set a
+      sx->pending_conn_done bit and test that in smtp_reap_banner() and
+      smtp_reap_ehlo().  That would let us also add the conn-timeout to the
+      cmd-timeout. */
+
+      if (f.running_in_test_harness && ob->connect_timeout == 999999)
+       errno = ETIMEDOUT;
+      set_errno_nohost(sx->addrlist,
+       errno == ETIMEDOUT ? ERRNO_CONNECTTIMEOUT : errno,
+       sx->verify ? US strerror(errno) : NULL,
+       DEFER, FALSE);
+      sx->send_quit = FALSE;
+      return DEFER;
+      }
+
+    /* really an error on an SMTP read */
     message = NULL;
     sx->send_quit = check_response(sx->conn_args.host, &errno, sx->addrlist->more_errno,
       sx->buffer, &code, &message, &pass_message);

diff --git a/test/runtest b/test/runtest
index a9927475e06dfdba8630a91ef9c7ea7618d05faf..bd0b9859b34edeef194b010d7387d7d49cde12a1 100755 (executable)
--- a/test/runtest
+++ b/test/runtest
@@ -492,10 +492,10 @@ RESET_AFTER_EXTRA_LINE_READ:
   # time used was fixed when I first started running automatic Exim tests.
 
   # Date/time in header lines and SMTP responses
-  s/[A-Z][a-z]{2},\s\d\d?\s[A-Z][a-z]{2}\s\d\d\d\d\s\d\d\:\d\d:\d\d\s[-+]\d{4}
+  s/[A-Z][a-z]{2},\s\d\d?\s[A-Z][a-z]{2}\s\d{4}\s\d\d\:\d\d:\d\d\s[-+]\d{4}
     /Tue, 2 Mar 1999 09:44:33 +0000/gx;
   # and in a French locale
-  s/\S{4},\s\d\d?\s[^,]+\s\d\d\d\d\s\d\d\:\d\d:\d\d\s[-+]\d{4}
+  s/\S{4},\s\d\d?\s[^,]+\s\d{4}\s\d\d\:\d\d:\d\d\s[-+]\d{4}
     /dim., 10 f\xE9vr 2019 20:05:49 +0000/gx;
 
   # Date/time in logs and in one instance of a filter test
@@ -1208,7 +1208,7 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if /^PDKIM \[[^[]+\] (Header hash|b) computed:/;
 
     # Not all platforms support TCP Fast Open, and the compile omits the check
-    if (s/\S+ in hosts_try_fastopen\? no \(option unset\)\n$//)
+    if (s/\S+ in hosts_try_fastopen\? (no \(option unset\)|yes \(matched "\*"\))\n$//)
       {
       $_ .= <IN>;
       s/ \.\.\. >>> / ... /;
@@ -1218,6 +1218,28 @@ RESET_AFTER_EXTRA_LINE_READ:
     next if /^(ppppp )?setsockopt FASTOPEN: Protocol not available$/;
     s/^(Connecting to .* \.\.\. sending) \d+ (nonTFO early-data)$/$1 dd $2/;
 
+    if (/^([0-9: ]*Connecting to [^ ]+ [^ ]+( from [^ ]+)?) \.\.\. .*TFO mode sendto, no data: EINPROGRESS$/)
+      {
+      $_ = $1 . " ... " . <IN>;
+      s/^(.* \.\.\.) [0-9: ]*connected$/$1 connected/;
+
+      if (/^Connecting to .* \.\.\. connected$/)
+       {
+       $_ .= <IN>;
+       if (/^(Connecting to .* \.\.\. )connected\n\s+SMTP(\(close\)>>|\(Connection refused\)<<)$/)
+         {
+         $_ = $1 . "failed: Connection refused\n" . <IN>;
+         s/^(Connecting .*)\n\s+SMTP\(close\)>>$/$1/;
+         }
+       elsif (/^(Connecting to .* \.\.\. connected\n)read response data: size=/)
+         { $_ = $1; }
+
+       # Date/time in SMTP banner
+       s/[A-Z][a-z]{2},\s\d\d?\s[A-Z][a-z]{2}\s\d{4}\s\d\d\:\d\d:\d\d\s[-+]\d{4}
+         /Tue, 2 Mar 1999 09:44:33 +0000/gx;
+       }
+      }
+
     # Specific pointer values reported for DB operations change from run to run
     s/^(\s*returned from EXIM_DBOPEN: )(0x)?[0-9a-f]+/${1}0xAAAAAAAA/;
     s/^(\s*EXIM_DBCLOSE.)(0x)?[0-9a-f]+/${1}0xAAAAAAAA/;

diff --git a/test/stderr/0227 b/test/stderr/0227
index e1f00897651d7aabc26cb87564b9641d68c1769c..4fd9d54ecd5196bf3e3c1a4278e28ef76fa35662 100644 (file)
--- a/test/stderr/0227
+++ b/test/stderr/0227
@@ -317,6 +317,7 @@ LOG: smtp_connection MAIN
 LOG: smtp_connection MAIN
   SMTP connection from root
 Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
+  SMTP(closed)<<
   SMTP(close)>>
 LOG: MAIN REJECT
   H=[V4NET.0.0.1] U=root sender verify defer for <bad@localhost1>: Could not complete sender verify callout: 127.0.0.1 [127.0.0.1] : Remote host closed connection in response to initial connection

diff --git a/test/stderr/0376 b/test/stderr/0376
index d08f4302e3bbd09f2aa7e9ef0a4a4e8ae79fe35f..334af5a9e47b4a63502ccc9f02dae870cebd4a67 100644 (file)
--- a/test/stderr/0376
+++ b/test/stderr/0376
@@ -655,6 +655,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP<< 250 OK
   SMTP>> RCPT TO:<myhost.test.ex-dddddddd-testing@otherhost51>
+  SMTP(Connection timed out)<<
 SMTP timeout
   SMTP(close)>>
 wrote callout cache domain record for otherhost51:
@@ -760,6 +761,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP<< 250 OK
   SMTP>> RCPT TO:<abcd@x.y.z>
+  SMTP(Connection timed out)<<
 SMTP timeout
   SMTP(close)>>
 wrote callout cache domain record for x.y.z:

diff --git a/test/stderr/0473 b/test/stderr/0473
index 65a39a9b77836cc118ef8a613d8d72a7e0412df4..2ab1628a41b99d33edc9b238c1436a6d4d7b51c5 100644 (file)
--- a/test/stderr/0473
+++ b/test/stderr/0473
@@ -19,6 +19,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP<< 250 OK
   SMTP>> RCPT TO:<r11@two.test.ex>
+  SMTP(Connection timed out)<<
 SMTP timeout
   SMTP(close)>>
 wrote callout cache domain record for two.test.ex:
@@ -43,6 +44,7 @@ callout cache: found domain record for two.test.ex
 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(Connection timed out)<<
   SMTP(close)>>
 SMTP timeout
 LOG: MAIN REJECT

diff --git a/test/stderr/0578 b/test/stderr/0578
index 54ccc563c4f87b174b2062c4b73825fcdc69ebb2..55525fc65db7d270b8b631d5768c4fa601d936cc 100644 (file)
--- a/test/stderr/0578
+++ b/test/stderr/0578
@@ -685,6 +685,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP>> RCPT TO:<myhost.test.ex-dddddddd-testing@otherhost51>
   SMTP<< 250 OK
+  SMTP(Connection timed out)<<
 SMTP timeout
   SMTP(close)>>
 wrote callout cache domain record for otherhost51:
@@ -796,6 +797,7 @@ Connecting to 127.0.0.1 [127.0.0.1]:1224 ... connected
   SMTP>> MAIL FROM:<>
   SMTP>> RCPT TO:<abcd@x.y.z>
   SMTP<< 250 OK
+  SMTP(Connection timed out)<<
 SMTP timeout
   SMTP(close)>>
 wrote callout cache domain record for x.y.z: