From: Jeremy Harris Date: Thu, 19 Nov 2020 19:05:54 +0000 (+0000) Subject: Logging: add I= element to transport-defer lines. Bug 2675 X-Git-Url: https://git.exim.org/users/heiko/exim.git/commitdiff_plain/5c161fa615ab4a2d40170fedd71d1b9a7f079ff6 Logging: add I= element to transport-defer lines. Bug 2675 --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index d62ceafd7..34b36ca9f 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -38668,6 +38668,7 @@ routing email addresses, but it does apply to &"byname"& lookups. client's ident port times out. .next .cindex "log" "incoming interface" +.cindex "log" "outgoing interface" .cindex "log" "local interface" .cindex "log" "local address and port" .cindex "TCP/IP" "logging local address and port" @@ -38676,7 +38677,10 @@ client's ident port times out. to the &"<="& line as an IP address in square brackets, tagged by I= and followed by a colon and the port number. The local interface and port are also added to other SMTP log lines, for example, &"SMTP connection from"&, to -rejection lines, and (despite the name) to outgoing &"=>"& and &"->"& lines. +rejection lines, and (despite the name) to outgoing +.new +&"=>"&, &"->"&, &"=="& and &"**"& lines. +.wen The latter can be disabled by turning off the &%outgoing_interface%& option. .next .cindex log "incoming proxy address" diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog index d56454ccc..16098d50e 100644 --- a/doc/doc-txt/ChangeLog +++ b/doc/doc-txt/ChangeLog @@ -140,6 +140,10 @@ JH/28 Fix spurious logging of select error. Some platforms, notably FreeBSD, a bug in the error-handling. This was benign apart from the log messages. +JH/29 Bug 2675: add outgoing-interface I= element to deferred "==" log lines, + for consistency with delivered "=>" and failed "**" lines. While we're + there, handle PRX and TFO. + Exim version 4.94 ----------------- diff --git a/src/src/deliver.c b/src/src/deliver.c index 9c4c1a746..4e6f08f89 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -1325,20 +1325,10 @@ else if (driver_kind) g = string_fmt_append(g, " defer (%d)", addr->basic_errno); if (addr->basic_errno > 0) - g = string_append(g, 2, US": ", - US strerror(addr->basic_errno)); + g = string_append(g, 2, US": ", US strerror(addr->basic_errno)); if (addr->host_used) - { - g = string_append(g, 5, - US" H=", addr->host_used->name, - US" [", addr->host_used->address, US"]"); - if (LOGGING(outgoing_port)) - { - int port = addr->host_used->port; - g = string_fmt_append(g, ":%d", port == PORT_NONE ? 25 : port); - } - } + g = d_hostlog(g, addr); if (LOGGING(deliver_time)) g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time)); diff --git a/test/confs/0179 b/test/confs/0179 index f18ab32e5..4efe92f94 100644 --- a/test/confs/0179 +++ b/test/confs/0179 @@ -8,7 +8,7 @@ primary_hostname = myhost.test.ex queue_run_in_order # incoming_interface is used here to get the _outgoing_ local port -log_selector = +outgoing_port +incoming_interface +log_selector = +outgoing_port +incoming_interface +received_recipients # ----- Routers ----- @@ -20,6 +20,7 @@ all: route_list = * 127.0.0.1 byname self = send transport = smtp + errors_to = "" no_more diff --git a/test/log/0179 b/test/log/0179 index de05f6462..614fea640 100644 --- a/test/log/0179 +++ b/test/log/0179 @@ -1,8 +1,18 @@ -1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss -1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss +1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for userx@domain.com +1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for abcd@domain.com 1999-03-02 09:44:33 Start queue run: pid=pppp -qqf 1999-03-02 09:44:33 10HmaX-0005vi-00 => userx@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1]:PORT_S I=[127.0.0.1]:ppppp C="250 OK" 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed 1999-03-02 09:44:33 10HmaY-0005vi-00 => abcd@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1]:PORT_S I=[127.0.0.1]:ppppp* C="250 OK" 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed 1999-03-02 09:44:33 End queue run: pid=pppp -qqf +1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss for userz@domain.com +1999-03-02 09:44:33 Start queue run: pid=pppp -qqf +1999-03-02 09:44:33 10HmaZ-0005vi-00 H=127.0.0.1 [127.0.0.1]:1111: SMTP error from remote mail server after MAIL FROM:<>: 450 not right now, sorry +1999-03-02 09:44:33 10HmaZ-0005vi-00 == userz@domain.com R=all T=smtp defer (-45) H=127.0.0.1 [127.0.0.1]:PORT_S I=[127.0.0.1]:ppppp: SMTP error from remote mail server after MAIL FROM:<>: 450 not right now, sorry +1999-03-02 09:44:33 End queue run: pid=pppp -qqf +1999-03-02 09:44:33 Start queue run: pid=pppp -qqf +1999-03-02 09:44:33 10HmaZ-0005vi-00 ** userz@domain.com R=all T=smtp H=127.0.0.1 [127.0.0.1]:PORT_S I=[127.0.0.1]:ppppp: SMTP error from remote mail server after RCPT TO:: 550 Recipient refused +1999-03-02 09:44:33 10HmaZ-0005vi-00 userz@domain.com: error ignored +1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed +1999-03-02 09:44:33 End queue run: pid=pppp -qqf diff --git a/test/log/2010 b/test/log/2010 index 5116b354e..2295e6860 100644 --- a/test/log/2010 +++ b/test/log/2010 @@ -6,7 +6,7 @@ 1999-03-02 09:44:33 End queue run: pid=pppp -qf 1999-03-02 09:44:33 Start queue run: pid=pppp -qf 1999-03-02 09:44:33 10HmaY-0005vi-00 H=127.0.0.1 [127.0.0.1]:1111: a TLS session is required, but the server did not offer TLS support -1999-03-02 09:44:33 10HmaY-0005vi-00 == userx@test.ex R=client T=send_to_server defer (-38) H=127.0.0.1 [127.0.0.1]:1111: a TLS session is required, but the server did not offer TLS support +1999-03-02 09:44:33 10HmaY-0005vi-00 == userx@test.ex R=client T=send_to_server defer (-38) H=127.0.0.1 [127.0.0.1]:PORT_D: a TLS session is required, but the server did not offer TLS support 1999-03-02 09:44:33 10HmaY-0005vi-00 ** userx@test.ex: retry timeout exceeded 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= <> R=10HmaY-0005vi-00 U=EXIMUSER P=local S=sss 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed diff --git a/test/log/2037 b/test/log/2037 index 3291debab..abe4b3ebd 100644 --- a/test/log/2037 +++ b/test/log/2037 @@ -1,7 +1,7 @@ 1999-03-02 09:44:33 U=CALLER F=<> temporarily rejected RCPT : Could not complete recipient verify callout: 127.0.0.1 [127.0.0.1] : SMTP error from remote mail server after RCPT TO:: 451 Temporary local problem - please try later 1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local-smtp S=sss for data_defer@test.ex 1999-03-02 09:44:33 10HmaY-0005vi-00 H=127.0.0.1 [127.0.0.1]:1111: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later -1999-03-02 09:44:33 10HmaY-0005vi-00 == data_defer@test.ex R=client T=t1 defer (-46) H=127.0.0.1 [127.0.0.1]:1111: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later +1999-03-02 09:44:33 10HmaY-0005vi-00 == data_defer@test.ex R=client T=t1 defer (-46) H=127.0.0.1 [127.0.0.1]:PORT_D: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later ******** SERVER ******** 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D diff --git a/test/log/2110 b/test/log/2110 index ef00023df..315dc244a 100644 --- a/test/log/2110 +++ b/test/log/2110 @@ -8,7 +8,7 @@ 1999-03-02 09:44:33 End queue run: pid=pppp -qf 1999-03-02 09:44:33 Start queue run: pid=pppp -qf 1999-03-02 09:44:33 10HmaY-0005vi-00 H=127.0.0.1 [127.0.0.1]:1111: a TLS session is required, but the server did not offer TLS support -1999-03-02 09:44:33 10HmaY-0005vi-00 == userx@test.ex R=client T=send_to_server defer (-38) H=127.0.0.1 [127.0.0.1]:1111: a TLS session is required, but the server did not offer TLS support +1999-03-02 09:44:33 10HmaY-0005vi-00 == userx@test.ex R=client T=send_to_server defer (-38) H=127.0.0.1 [127.0.0.1]:PORT_D: a TLS session is required, but the server did not offer TLS support 1999-03-02 09:44:33 10HmaY-0005vi-00 ** userx@test.ex: retry timeout exceeded 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= <> R=10HmaY-0005vi-00 U=EXIMUSER P=local S=sss 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed diff --git a/test/log/2137 b/test/log/2137 index 3291debab..abe4b3ebd 100644 --- a/test/log/2137 +++ b/test/log/2137 @@ -1,7 +1,7 @@ 1999-03-02 09:44:33 U=CALLER F=<> temporarily rejected RCPT : Could not complete recipient verify callout: 127.0.0.1 [127.0.0.1] : SMTP error from remote mail server after RCPT TO:: 451 Temporary local problem - please try later 1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local-smtp S=sss for data_defer@test.ex 1999-03-02 09:44:33 10HmaY-0005vi-00 H=127.0.0.1 [127.0.0.1]:1111: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later -1999-03-02 09:44:33 10HmaY-0005vi-00 == data_defer@test.ex R=client T=t1 defer (-46) H=127.0.0.1 [127.0.0.1]:1111: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later +1999-03-02 09:44:33 10HmaY-0005vi-00 == data_defer@test.ex R=client T=t1 defer (-46) H=127.0.0.1 [127.0.0.1]:PORT_D: SMTP error from remote mail server after end of data: 451 Temporary local problem - please try later ******** SERVER ******** 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D diff --git a/test/runtest b/test/runtest index d4e469b9f..b5ace4ee3 100755 --- a/test/runtest +++ b/test/runtest @@ -780,7 +780,7 @@ RESET_AFTER_EXTRA_LINE_READ: # This handles "connection from" and the like, when the port is given if (!/listening for SMTP on/ && !/Connecting to/ && !/=>/ && !/->/ - && !/\*>/ && !/Connection refused/) + && !/\*>/&& !/==/ && !/\*\*/ && !/Connection refused/ && !/in response to/) { s/\[([a-z\d:]+|\d+(?:\.\d+){3})\]:(\d+)/"[".$1."]:".new_value($2,"%s",\$next_port)/ie; } diff --git a/test/scripts/0000-Basic/0179 b/test/scripts/0000-Basic/0179 index 932cc11fe..6a7b2253b 100644 --- a/test/scripts/0000-Basic/0179 +++ b/test/scripts/0000-Basic/0179 @@ -33,3 +33,38 @@ QUIT **** exim -odi -qqf **** +# +# Defer from receiving host +exim -odq userz@domain.com +. +**** +server PORT_S +220 ESMTP +EHLO +250-OK +250 HELP +MAIL FROM: +450 not right now, sorry +QUIT +250 OK +**** +exim -odi -qqf +**** +# +# Deny from receiving host +server PORT_S +220 ESMTP +EHLO +250-OK +250 HELP +MAIL FROM: +250 Sender OK +RCPT TO: +550 Recipient refused +QUIT +250 OK +**** +exim -odi -qqf +**** +# +no_msglog_check diff --git a/test/stdout/0179 b/test/stdout/0179 index 9013698df..c8db94620 100644 --- a/test/stdout/0179 +++ b/test/stdout/0179 @@ -6,7 +6,7 @@ Connection request from [127.0.0.1] EHLO myhost.test.ex 250-OK 250 HELP -MAIL FROM: +MAIL FROM:<> 250 Sender OK RCPT TO: 250 Recipient OK @@ -22,7 +22,7 @@ Date: Tue, 2 Mar 1999 09:44:33 +0000 . 250 OK -MAIL FROM: +MAIL FROM:<> 250 Sender OK RCPT TO: 250 Recipient OK @@ -41,3 +41,27 @@ Date: Tue, 2 Mar 1999 09:44:33 +0000 QUIT 250 OK End of script +Listening on port 1224 ... +Connection request from [127.0.0.1] +220 ESMTP +EHLO myhost.test.ex +250-OK +250 HELP +MAIL FROM:<> +450 not right now, sorry +QUIT +250 OK +End of script +Listening on port 1224 ... +Connection request from [127.0.0.1] +220 ESMTP +EHLO myhost.test.ex +250-OK +250 HELP +MAIL FROM:<> +250 Sender OK +RCPT TO: +550 Recipient refused +QUIT +250 OK +End of script