Event for auth fail: client side

12 files changed, 202 insertions, 26 deletions

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 &<<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 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 <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
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 <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 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