From eebcfa1ccd5ff02bc45b7945eade84ad22f39c95 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sun, 26 May 2019 11:52:55 +0100 Subject: [PATCH] Debug: align tracing out for TFO connections with plain ones --- src/src/smtp_out.c | 2 +- src/src/transports/smtp.c | 27 +++++++++++++++++++++++---- test/runtest | 28 +++++++++++++++++++++++++--- test/stderr/0227 | 1 + test/stderr/0376 | 2 ++ test/stderr/0473 | 2 ++ test/stderr/0578 | 2 ++ 7 files changed, 56 insertions(+), 8 deletions(-) diff --git a/src/src/smtp_out.c b/src/src/smtp_out.c index d8cb42e01..ea052b58a 100644 --- 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 6ce4c9ded..94c1fe40c 100644 --- 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 a9927475e..bd0b9859b 100755 --- 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$//) { $_ .= ; 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 . " ... " . ; + s/^(.* \.\.\.) [0-9: ]*connected$/$1 connected/; + + if (/^Connecting to .* \.\.\. connected$/) + { + $_ .= ; + if (/^(Connecting to .* \.\.\. )connected\n\s+SMTP(\(close\)>>|\(Connection refused\)<<)$/) + { + $_ = $1 . "failed: Connection refused\n" . ; + 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 e1f008976..4fd9d54ec 100644 --- 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 : 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 d08f4302e..334af5a9e 100644 --- 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: + 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: + 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 65a39a9b7..2ab1628a4 100644 --- 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: + 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 54ccc563c..55525fc65 100644 --- 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: 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: SMTP<< 250 OK + SMTP(Connection timed out)<< SMTP timeout SMTP(close)>> wrote callout cache domain record for x.y.z: -- 2.30.2