Debug: align tracing out for TFO connections with plain ones
authorJeremy Harris <jgh146exb@wizmail.org>
Sun, 26 May 2019 10:52:55 +0000 (11:52 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Sun, 26 May 2019 14:05:51 +0000 (15:05 +0100)
src/src/smtp_out.c
src/src/transports/smtp.c
test/runtest
test/stderr/0227
test/stderr/0376
test/stderr/0473
test/stderr/0578

index d8cb42e..ea052b5 100644 (file)
@@ -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;
index 6ce4c9d..94c1fe4 100644 (file)
@@ -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);
index a992747..bd0b985 100755 (executable)
@@ -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/;
index e1f0089..4fd9d54 100644 (file)
@@ -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
index d08f430..334af5a 100644 (file)
@@ -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:
index 65a39a9..2ab1628 100644 (file)
@@ -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
index 54ccc56..55525fc 100644 (file)
@@ -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: