Event for auth fail: client side

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 935a78a39d2252b6fb9a61b499bf763575e6fb19..151ce4639fd1ff7b8d36fcdd0303ea134ec44e7f 100644 (file)
--- 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 &<<CHAPevents>>&) 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 <<CHAPevents>> 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 &<<CHAPevents>>&) 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 <<CHAPevents>> 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 bd7f02cfaf3415032b7f033c4dbb07c1acdaf7e9..d9a9f6cdaa48a2714fb1c6a01d3871ce0b59d116 100644 (file)
--- 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 4a5c44714fcac9735389b004485ab96269cf6060..11e7436b917986af08d27fd13841d42a1f1886c0 100644 (file)
--- 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 6eee04d03124ffa77964065129a82f07cc0f50e6..d7f251b0b2cb542308739feae4cad56613af64e6 100644 (file)
--- 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 cc18c0692ffa4325e2f32a8721cb3d7388252dae..3959304a2202a1a48888393a1e73400c3af7cb56 100644 (file)
--- 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 42413b4e49c8444ab1f36662313f095312a89ca7..887f2184db778c75905865d13cd7616d125251cd 100644 (file)
--- 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 (file)
index 0000000..b98db16
--- /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 2de0ec65508bddfb7b0602bf9e267336699d19ff..5f817f43d2524940c663cebd7494ac829a83bfe8 100644 (file)
--- 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 <testname> 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 <testname> 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 (file)
index 0000000..5567854
--- /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 <login> 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 <userx> domain <domain.com> errno <-42> errstr <authentication required but authentication attempt(s) failed> router <force> transport <smtp_force>
+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 <userx> domain <domain.com> errno <-42> errstr <authentication required but authentication attempt(s) failed> router <force> transport <smtp_force>
+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 <userx> domain <domain.com> errstr <authentication required but authentication attempt(s) failed: retry timeout exceeded>
+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 dca36042e48c47a75bda0ada5ab4668078fd4939..53ca36096f93ce5add4a1d1e16e41cdba1abec0b 100644 (file)
--- 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 (file)
index 0000000..6f45943
--- /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 (file)
index 0000000..a0c8deb
--- /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