From 9b3a1518f52a1de4469c85af8dde74489b974a66 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Thu, 21 Jul 2022 16:41:25 +0100 Subject: [PATCH] Event for auth fail: client side --- doc/doc-docbook/spec.xfpt | 22 +++++++-- doc/doc-txt/NewStuff | 2 +- src/src/smtp_in.c | 33 ++++++++----- src/src/transports/smtp.c | 21 +++++++-- test/aux-fixed/event-logger-acl | 6 +-- test/confs/3418 | 8 +++- test/confs/3419 | 65 ++++++++++++++++++++++++++ test/log/3418 | 4 +- test/log/3419 | 24 ++++++++++ test/rejectlog/3418 | 4 +- test/scripts/3418-plaintext-event/3419 | 21 +++++++++ test/stdout/3419 | 18 +++++++ 12 files changed, 202 insertions(+), 26 deletions(-) create mode 100644 test/confs/3419 create mode 100644 test/log/3419 create mode 100644 test/scripts/3418-plaintext-event/3419 create mode 100644 test/stdout/3419 diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index 935a78a39..151ce4639 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -27648,13 +27648,15 @@ Successful authentication sets up information used by the &%authresults%& expansion item. .new -.cindex authentication "failure event" +.cindex authentication "failure event, server" If an authenticator is run and does not succeed, an event (see &<>&) of type "auth:fail" is raised. While the event is being processed the variables &$sender_host_authenticated$& (with the authenticator name) -and &$authenticated_fail_id$& (as set by the suthenticator &%server_set_id%& option) +and &$authenticated_fail_id$& (as set by the authenticator &%server_set_id%& option) will be valid. +If the event is serviced and a string is returned then the string will be logged +instead of the default log line. See <> for details on events. .wen @@ -27734,6 +27736,19 @@ If the result of the authentication attempt is a temporary error or a timeout, Exim abandons trying to send the message to the host for the moment. It will try again later. If there are any backup hosts available, they are tried in the usual way. + +.new +.next +.cindex authentication "failure event, client" +If the response to authentication is a permanent error (5&'xx'& code), +an event (see &<>&) of type "auth:fail" is raised. +While the event is being processed the variable +&$sender_host_authenticated$& (with the authenticator name) +will be valid. +If the event is serviced and a string is returned then the string will be logged. +See <> for details on events. +.wen + .next If the response to authentication is a permanent error (5&'xx'& code), Exim carries on searching the list of authenticators and tries another one if @@ -42710,7 +42725,7 @@ expansion must check this, as it will be called for every possible event type. The current list of events is: .itable all 0 0 4 25* left 10* center 15* center 50* left -.row auth:fail after main "per driver per authentication attempt" +.row auth:fail after both "per driver per authentication attempt" .row dane:fail after transport "per connection" .row msg:complete after main "per message" .row msg:defer after transport "per message per delivery try" @@ -42777,6 +42792,7 @@ The expansion of the event_action option should normally return an empty string. Should it return anything else the following will be forced: .itable all 0 0 2 20* left 80* left +.row auth:fail "log information to write" .row tcp:connect "do not connect" .row tls:cert "refuse verification" .row smtp:connect "close connection" diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index bd7f02cfa..d9a9f6cda 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -11,7 +11,7 @@ Version 4.97 1. The expansion-test faciility (exim -be) can set variables. - 2. An event on a failing SMTP AUTH, server side. + 2. An event on a failing SMTP AUTH, for both client and server operations. Version 4.96 ------------ diff --git a/src/src/smtp_in.c b/src/src/smtp_in.c index 4a5c44714..11e7436b9 100644 --- a/src/src/smtp_in.c +++ b/src/src/smtp_in.c @@ -4099,11 +4099,16 @@ while (done <= 0) { DEBUG(D_auth) debug_printf("tls auth succeeded\n"); } else { - uschar * save_name = sender_host_authenticated; DEBUG(D_auth) debug_printf("tls auth not succeeded\n"); - sender_host_authenticated = au->name; - (void) event_raise(event_action, US"auth:fail", s, NULL); - sender_host_authenticated = save_name; +#ifndef DISABLE_EVENT + { + uschar * save_name = sender_host_authenticated, * logmsg; + sender_host_authenticated = au->name; + if ((logmsg = event_raise(event_action, US"auth:fail", s, NULL))) + log_write(0, LOG_MAIN, "%s", logmsg); + sender_host_authenticated = save_name; + } +#endif } } break; @@ -4208,13 +4213,19 @@ while (done <= 0) smtp_printf("%s\r\n", FALSE, smtp_resp); if (rc != OK) { - uschar * save_name = sender_host_authenticated; - - log_write(0, LOG_MAIN|LOG_REJECT, "%s authenticator failed for %s: %s", - au->name, host_and_ident(FALSE), errmsg); - sender_host_authenticated = au->name; - (void) event_raise(event_action, US"auth:fail", smtp_resp, NULL); - sender_host_authenticated = save_name; + uschar * logmsg = NULL; +#ifndef DISABLE_EVENT + {uschar * save_name = sender_host_authenticated; + sender_host_authenticated = au->name; + logmsg = event_raise(event_action, US"auth:fail", smtp_resp, NULL); + sender_host_authenticated = save_name; + } +#endif + if (logmsg) + log_write(0, LOG_MAIN|LOG_REJECT, "%s", logmsg); + else + log_write(0, LOG_MAIN|LOG_REJECT, "%s authenticator failed for %s: %s", + au->name, host_and_ident(FALSE), errmsg); } } else diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c index 6eee04d03..d7f251b0b 100644 --- a/src/src/transports/smtp.c +++ b/src/src/transports/smtp.c @@ -1476,7 +1476,7 @@ rc = (au->info->clientcode)(au, sx, ob->command_timeout, sx->buffer, sizeof(sx->buffer)); sx->outblock.authenticating = FALSE; driver_srcfile = authenticator_name = NULL; driver_srcline = 0; -DEBUG(D_transport) debug_printf("%s authenticator yielded %d\n", au->name, rc); +DEBUG(D_transport) debug_printf("%s authenticator yielded %s\n", au->name, rc_names[rc]); /* A temporary authentication failure must hold up delivery to this host. After a permanent authentication failure, we carry on @@ -1500,10 +1500,25 @@ switch(rc) /* Failure after reading a response */ case FAIL: + { + uschar * logmsg = NULL; + if (errno != 0 || sx->buffer[0] != '5') return FAIL; - log_write(0, LOG_MAIN, "%s authenticator failed H=%s [%s] %s", - au->name, host->name, host->address, sx->buffer); +#ifndef DISABLE_EVENT + { + uschar * save_name = sender_host_authenticated; + sender_host_authenticated = au->name; + if ((logmsg = event_raise(sx->conn_args.tblock->event_action, US"auth:fail", + sx->buffer, NULL))) + log_write(0, LOG_MAIN, "%s", logmsg); + sender_host_authenticated = save_name; + } +#endif + if (!logmsg) + log_write(0, LOG_MAIN, "%s authenticator failed H=%s [%s] %s", + au->name, host->name, host->address, sx->buffer); break; + } /* Failure by some other means. In effect, the authenticator decided it wasn't prepared to handle this case. Typically this diff --git a/test/aux-fixed/event-logger-acl b/test/aux-fixed/event-logger-acl index cc18c0692..3959304a2 100644 --- a/test/aux-fixed/event-logger-acl +++ b/test/aux-fixed/event-logger-acl @@ -88,6 +88,6 @@ ev_auth: logger: warn logwrite = event $event_name set acl_m1 = ${listextract{1}{$event_name}} - accept condition = ${if !inlist{$acl_m1}{tcp:smtp:msg:auth}} - logwrite = UNEXPECTED $event_name - accept acl = ev_$acl_m1 + accept condition = ${if inlist{$acl_m1}{tcp:smtp:msg:auth}} + acl = ev_$acl_m1 + accept logwrite = UNEXPECTED $event_name diff --git a/test/confs/3418 b/test/confs/3418 index 42413b4e4..887f2184d 100644 --- a/test/confs/3418 +++ b/test/confs/3418 @@ -11,7 +11,7 @@ domainlist local_domains = test.ex : *.test.ex auth_advertise_hosts = 10.0.0.5 trusted_users = CALLER -event_action = ${acl {logger}} +event_action = ${acl {auth_event}} # ----- ACL ----- @@ -19,6 +19,12 @@ begin acl .include DIR/aux-fixed/event-logger-acl +auth_event: + warn acl = logger + accept condition = ${if eq {$event_name}{auth:fail}} + message = custom-message: $sender_host_authenticated authenticator failed \ + H=$sender_fullhost [$sender_host_address] $event_data $authenticated_fail_id + # ----- Authentication ----- diff --git a/test/confs/3419 b/test/confs/3419 new file mode 100644 index 000000000..b98db16e6 --- /dev/null +++ b/test/confs/3419 @@ -0,0 +1,65 @@ +# Exim test configuration 3419 + +.include DIR/aux-var/std_conf_prefix + +log_selector = +smtp_mailauth +primary_hostname = myhost.test.ex + +# ----- Main settings ----- + +acl_smtp_rcpt = accept + + +# ----- ACL ----- + +begin acl + +.include DIR/aux-fixed/event-logger-acl + +auth_event: + warn acl = logger + accept condition = ${if eq {$event_name}{auth:fail}} + message = custom-message: $sender_host_authenticated authenticator failed H=$host [$host_address] $event_data + +# ----- Authentication ----- + +begin authenticators + +login: + driver = plaintext + public_name = LOGIN + client_send = : userx : secret + client_set_id = userx + +# ----- Routers ----- + +begin routers + +force: + driver = manualroute + route_list = domain.com 127.0.0.1 byname + self = send + transport = smtp_force + errors_to = "" + +# ----- Transports ----- + +begin transports + +smtp_force: + driver = smtp + port = PORT_S + hosts_try_fastopen = : + hosts_require_auth = * + event_action = ${acl {auth_event}} + + +# ----- Retry ----- + + +begin retry + +* auth_failed +* * F,1h,10m + +# End diff --git a/test/log/3418 b/test/log/3418 index 2de0ec655..5f817f43d 100644 --- a/test/log/3418 +++ b/test/log/3418 @@ -1,6 +1,6 @@ -1999-03-02 09:44:33 testname authenticator failed for (testing.testing) [10.0.0.5] U=CALLER: 535 Incorrect authentication data (set_id=rx secret) 1999-03-02 09:44:33 event auth:fail 1999-03-02 09:44:33 . "auth fail" event_data <535 Incorrect authentication data> sender_host_authenticated authenticated_fail_id < (set_id=rx secret)> -1999-03-02 09:44:33 testname authenticator failed for (testing.testing) [10.0.0.5] U=CALLER: 501 Invalid base64 data +1999-03-02 09:44:33 custom-message: testname authenticator failed H=(testing.testing) [10.0.0.5] [10.0.0.5] 535 Incorrect authentication data (set_id=rx secret) 1999-03-02 09:44:33 event auth:fail 1999-03-02 09:44:33 . "auth fail" event_data <501 Invalid base64 data> sender_host_authenticated authenticated_fail_id <> +1999-03-02 09:44:33 custom-message: testname authenticator failed H=(testing.testing) [10.0.0.5] [10.0.0.5] 501 Invalid base64 data diff --git a/test/log/3419 b/test/log/3419 new file mode 100644 index 000000000..5567854d2 --- /dev/null +++ b/test/log/3419 @@ -0,0 +1,24 @@ +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 10HmaX-0005vi-00 event tcp:connect +1999-03-02 09:44:33 10HmaX-0005vi-00 . [127.0.0.1]:1111 +1999-03-02 09:44:33 10HmaX-0005vi-00 event smtp:connect +1999-03-02 09:44:33 10HmaX-0005vi-00 . [127.0.0.1] -> [127.0.0.1]:PORT_S +1999-03-02 09:44:33 10HmaX-0005vi-00 . banner <220 ESMTP> +1999-03-02 09:44:33 10HmaX-0005vi-00 event smtp:ehlo +1999-03-02 09:44:33 10HmaX-0005vi-00 . [127.0.0.1] -> [127.0.0.1]:PORT_S +1999-03-02 09:44:33 10HmaX-0005vi-00 . ehlo-resp <250-OK\n250-HELP\n250 AUTH LOGIN> +1999-03-02 09:44:33 10HmaX-0005vi-00 event auth:fail +1999-03-02 09:44:33 10HmaX-0005vi-00 . "auth fail" event_data <599 no way, man> sender_host_authenticated authenticated_fail_id <> +1999-03-02 09:44:33 10HmaX-0005vi-00 custom-message: login authenticator failed H=127.0.0.1 [127.0.0.1] 599 no way, man +1999-03-02 09:44:33 10HmaX-0005vi-00 event tcp:close +1999-03-02 09:44:33 10HmaX-0005vi-00 . [127.0.0.1] -> [127.0.0.1]:PORT_S +1999-03-02 09:44:33 10HmaX-0005vi-00 event msg:host:defer +1999-03-02 09:44:33 10HmaX-0005vi-00 . host deferral ip <127.0.0.1> port <1224> fqdn <127.0.0.1> local_part domain errno <-42> errstr router transport +1999-03-02 09:44:33 10HmaX-0005vi-00 event msg:defer +1999-03-02 09:44:33 10HmaX-0005vi-00 . message deferral ip <127.0.0.1> port <1224> fqdn <127.0.0.1> local_part domain errno <-42> errstr router transport +1999-03-02 09:44:33 10HmaX-0005vi-00 == userx@domain.com R=force T=smtp_force defer (-42): authentication required but authentication attempt(s) failed +1999-03-02 09:44:33 10HmaX-0005vi-00 ** userx@domain.com: retry timeout exceeded +1999-03-02 09:44:33 10HmaX-0005vi-00 event msg:fail:delivery +1999-03-02 09:44:33 10HmaX-0005vi-00 . refused by fdqn <> local_part domain errstr +1999-03-02 09:44:33 10HmaX-0005vi-00 userx@domain.com: error ignored +1999-03-02 09:44:33 10HmaX-0005vi-00 Completed diff --git a/test/rejectlog/3418 b/test/rejectlog/3418 index dca36042e..53ca36096 100644 --- a/test/rejectlog/3418 +++ b/test/rejectlog/3418 @@ -1,2 +1,2 @@ -1999-03-02 09:44:33 testname authenticator failed for (testing.testing) [10.0.0.5] U=CALLER: 535 Incorrect authentication data (set_id=rx secret) -1999-03-02 09:44:33 testname authenticator failed for (testing.testing) [10.0.0.5] U=CALLER: 501 Invalid base64 data +1999-03-02 09:44:33 custom-message: testname authenticator failed H=(testing.testing) [10.0.0.5] [10.0.0.5] 535 Incorrect authentication data (set_id=rx secret) +1999-03-02 09:44:33 custom-message: testname authenticator failed H=(testing.testing) [10.0.0.5] [10.0.0.5] 501 Invalid base64 data diff --git a/test/scripts/3418-plaintext-event/3419 b/test/scripts/3418-plaintext-event/3419 new file mode 100644 index 000000000..6f4594382 --- /dev/null +++ b/test/scripts/3418-plaintext-event/3419 @@ -0,0 +1,21 @@ +# plaintext client fail event +need_ipv4 +# +server PORT_S +220 ESMTP +EHLO +250-OK +250-HELP +250 AUTH LOGIN +AUTH LOGIN +334 VXNlciBOYW1l +dXNlcng +334 UGFzc3dvcmQ= +c2VjcmV0 +599 no way, man +QUIT +250 OK +**** +exim -odi userx@domain.com +. +no_msglog_check diff --git a/test/stdout/3419 b/test/stdout/3419 new file mode 100644 index 000000000..a0c8deb59 --- /dev/null +++ b/test/stdout/3419 @@ -0,0 +1,18 @@ + +******** SERVER ******** +Listening on port 1224 ... +Connection request from [127.0.0.1] +220 ESMTP +EHLO myhost.test.ex +250-OK +250-HELP +250 AUTH LOGIN +AUTH LOGIN +334 VXNlciBOYW1l +dXNlcng= +334 UGFzc3dvcmQ= +c2VjcmV0 +599 no way, man +QUIT +250 OK +End of script -- 2.30.2