Additional DEBUG logging on authc failures (#137941)

tvernum · web-flow · commit 7bab8ddcfccb · 2025-11-13T09:35:02.000+01:00
Adds two sets of DEBUG logging for authentication failures

1. In Pluggable authentication chain, log the failure reason if
   authentication is terminated. Without this the actual failure
   reason is lost becauser we return a generic error to the client.
2. For all authentication failures, add a general debug log in
   `AuthenticatorChain` so that we know that every authentication
   failure is logged somewhere, even if the specific chain handler
   doesn't log it.
   We also add a trace log for successful authentication
diff --git a/docs/changelog/137941.yaml b/docs/changelog/137941.yaml
@@ -0,0 +1,5 @@
+pr: 137941
+summary: Additional DEBUG logging on authc failures
+area: Authentication
+type: enhancement
+issues: []
diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/Authenticator.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/Authenticator.java
@@ -23,6 +23,7 @@
 import java.io.IOException;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.stream.Collectors;
 
 /**
  * The Authenticator interface represents an authentication mechanism or a group of similar authentication mechanisms.
@@ -241,5 +242,17 @@ public void addUnsuccessfulMessageToMetadata(final ElasticsearchSecurityExceptio
                 ese.addMetadata("es.additional_unsuccessful_credentials", getUnsuccessfulMessages());
             }
         }
+
+        @Override
+        public String toString() {
+            return Strings.format(
+                "%s{tokens=%s, messages=%s}",
+                getClass().getSimpleName(),
+                this.authenticationTokens.stream()
+                    .map(t -> t.getClass().getSimpleName() + ":" + t.principal())
+                    .collect(Collectors.joining(",", "[", "]")),
+                this.unsuccessfulMessages
+            );
+        }
     }
 }
diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticatorChain.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticatorChain.java
@@ -13,6 +13,7 @@
 import org.elasticsearch.action.ActionListener;
 import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.util.concurrent.ThreadContext;
+import org.elasticsearch.core.Strings;
 import org.elasticsearch.node.Node;
 import org.elasticsearch.xpack.core.common.IteratingActionListener;
 import org.elasticsearch.xpack.core.security.authc.Authentication;
@@ -83,11 +84,16 @@ void authenticate(Authenticator.Context context, ActionListener<Authentication>
         assert false == context.getDefaultOrderedRealmList().isEmpty() : "realm list must not be empty";
         // Check whether authentication is an operator user and mark the threadContext if necessary
         // before returning the authentication object
-        final ActionListener<Authentication> listener = originalListener.map(authentication -> {
+        final ActionListener<Authentication> listener = ActionListener.wrap(authentication -> {
             assert authentication != null;
             operatorPrivilegesService.maybeMarkOperatorUser(authentication, context.getThreadContext());
-            return authentication;
+            logger.trace(() -> Strings.format("Authentication for [%s]", authentication));
+            originalListener.onResponse(authentication);
+        }, ex -> {
+            logger.debug(() -> Strings.format("Authentication for context [%s] failed", context), ex);
+            originalListener.onFailure(ex);
         });
+
         // If a token is directly provided in the context, authenticate with it
         if (context.getMostRecentAuthenticationToken() != null) {
             doAuthenticate(context, listener);
diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/PluggableAuthenticatorChain.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/PluggableAuthenticatorChain.java
@@ -96,6 +96,14 @@ private BiConsumer<CustomAuthenticator, ActionListener<AuthenticationResult<Auth
                         iteratingListener.onResponse(response);
                     } else if (response.getStatus() == AuthenticationResult.Status.TERMINATE) {
                         final Exception ex = response.getException();
+                        logger.debug(
+                            () -> format(
+                                "Authentication of token [%s] was terminated: %s (caused by: %s)",
+                                token.principal(),
+                                response.getMessage(),
+                                ex
+                            )
+                        );
                         if (ex == null) {
                             iteratingListener.onFailure(context.getRequest().authenticationFailed(token));
                         } else {
diff --git a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/AuthenticatorChainTests.java b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/AuthenticatorChainTests.java
@@ -40,6 +40,7 @@
 import java.io.IOException;
 import java.util.Collections;
 import java.util.List;
+import java.util.regex.Pattern;
 
 import static org.elasticsearch.test.ActionListenerUtils.anyActionListener;
 import static org.hamcrest.Matchers.containsString;
@@ -321,7 +322,9 @@ public void testAuthenticateFallbackAndAnonymous() throws IOException {
     }
 
     public void testContextWithDirectWrongTokenFailsAuthn() {
-        final Authenticator.Context context = createAuthenticatorContext(mock(AuthenticationToken.class));
+        final AuthenticationToken token = mock(AuthenticationToken.class);
+        when(token.principal()).thenReturn("MOCK_USER");
+        final Authenticator.Context context = createAuthenticatorContext(token);
         doCallRealMethod().when(serviceAccountAuthenticator).authenticate(eq(context), anyActionListener());
         doCallRealMethod().when(oAuth2TokenAuthenticator).authenticate(eq(context), anyActionListener());
         doCallRealMethod().when(apiKeyAuthenticator).authenticate(eq(context), anyActionListener());
@@ -335,6 +338,20 @@ public void testContextWithDirectWrongTokenFailsAuthn() {
             return null;
         }).when(realmsAuthenticator).authenticate(eq(context), any());
         final PlainActionFuture<Authentication> future = new PlainActionFuture<>();
+
+        Loggers.setLevel(LogManager.getLogger(AuthenticatorChain.class), Level.DEBUG);
+        final MockLog mockLog = MockLog.capture(AuthenticatorChain.class);
+        mockLog.addExpectation(
+            new MockLog.PatternSeenEventExpectation(
+                "debug-failure",
+                AuthenticatorChain.class.getName(),
+                Level.DEBUG,
+                Pattern.quote("Authentication for context [Context{tokens=[")
+                    + "AuthenticationToken\\$.*:MOCK_USER"
+                    + Pattern.quote("], messages=[]}] failed")
+            )
+        );
+
         authenticatorChain.authenticate(context, future);
         final ElasticsearchSecurityException e = expectThrows(ElasticsearchSecurityException.class, future::actionGet);
         assertThat(e.getMessage(), containsString("failed to authenticate"));
@@ -345,6 +362,8 @@ public void testContextWithDirectWrongTokenFailsAuthn() {
         verify(realmsAuthenticator, never()).extractCredentials(any());
         verifyNoMoreInteractions(authenticationContextSerializer);
         verifyNoMoreInteractions(operatorPrivilegesService);
+        mockLog.assertAllExpectationsMatched();
+
         // OR 2. realms fail the token
         doAnswer(invocationOnMock -> {
             @SuppressWarnings("unchecked")
diff --git a/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/PluggableAuthenticatorChainTests.java b/x-pack/plugin/security/src/test/java/org/elasticsearch/xpack/security/authc/PluggableAuthenticatorChainTests.java
@@ -6,23 +6,32 @@
  */
 package org.elasticsearch.xpack.security.authc;
 
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.elasticsearch.ElasticsearchSecurityException;
 import org.elasticsearch.action.ActionListener;
+import org.elasticsearch.action.support.PlainActionFuture;
+import org.elasticsearch.common.logging.Loggers;
 import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.common.util.concurrent.ThreadContext;
 import org.elasticsearch.core.Nullable;
+import org.elasticsearch.rest.RestStatus;
 import org.elasticsearch.test.ESTestCase;
+import org.elasticsearch.test.MockLog;
 import org.elasticsearch.xpack.core.security.authc.Authentication;
 import org.elasticsearch.xpack.core.security.authc.AuthenticationResult;
 import org.elasticsearch.xpack.core.security.authc.AuthenticationTestHelper;
 import org.elasticsearch.xpack.core.security.authc.AuthenticationToken;
 import org.elasticsearch.xpack.core.security.authc.CustomAuthenticator;
 import org.elasticsearch.xpack.core.security.user.User;
 import org.junit.Before;
+import org.mockito.Mockito;
 
 import java.util.List;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.atomic.AtomicReference;
 
+import static org.elasticsearch.test.TestMatchers.throwableWithMessage;
 import static org.hamcrest.Matchers.equalTo;
 import static org.hamcrest.Matchers.notNullValue;
 
@@ -87,13 +96,15 @@ public String getValue() {
     public class TokenAAuthenticator implements CustomAuthenticator {
 
         private final String id;
+        private boolean succeed;
 
         public TokenAAuthenticator() {
-            id = "1";
+            this("1", true);
         }
 
-        public TokenAAuthenticator(String id) {
+        public TokenAAuthenticator(String id, boolean succeed) {
             this.id = id;
+            this.succeed = succeed;
         }
 
         @Override
@@ -109,9 +120,13 @@ public boolean supports(AuthenticationToken token) {
         @Override
         public void authenticate(@Nullable AuthenticationToken token, ActionListener<AuthenticationResult<Authentication>> listener) {
             if (token instanceof TestTokenA testToken) {
-                User user = new User("token-a-auth-user-" + id + "-" + testToken.getValue());
-                Authentication auth = AuthenticationTestHelper.builder().user(user).build(false);
-                listener.onResponse(AuthenticationResult.success(auth));
+                if (succeed) {
+                    User user = new User("token-a-auth-user-" + id + "-" + testToken.getValue());
+                    Authentication auth = AuthenticationTestHelper.builder().user(user).build(false);
+                    listener.onResponse(AuthenticationResult.success(auth));
+                } else {
+                    listener.onResponse(AuthenticationResult.terminate("token-a-fail-" + id + "-" + testToken.getValue()));
+                }
             } else {
                 listener.onResponse(AuthenticationResult.notHandled());
             }
@@ -243,7 +258,7 @@ public void onFailure(Exception e) {
     public void testAuthenticateWhenTokenSupportedByBothAuthenticatorsInChain() throws Exception {
 
         PluggableAuthenticatorChain chain = new PluggableAuthenticatorChain(
-            List.of(new TokenAAuthenticator("foo"), new TokenAAuthenticator("bar"))
+            List.of(new TokenAAuthenticator("foo", true), new TokenAAuthenticator("bar", true))
         );
         TestTokenA testToken = new TestTokenA("test-value");
 
@@ -286,7 +301,7 @@ public void onFailure(Exception e) {
     public void testAuthenticateWhenTokenSupportedByNoAuthenticatorsInChain() throws Exception {
 
         PluggableAuthenticatorChain chain = new PluggableAuthenticatorChain(
-            List.of(new TokenAAuthenticator("foo"), new TokenAAuthenticator("bar"))
+            List.of(new TokenAAuthenticator("foo", true), new TokenAAuthenticator("bar", true))
         );
         AuthenticationToken unknownToken = new AuthenticationToken() {
             @Override
@@ -338,7 +353,37 @@ public void onFailure(Exception e) {
         assertThat(result.getStatus(), equalTo(AuthenticationResult.Status.CONTINUE));
     }
 
+    public void testAuthenticationTermination() throws Exception {
+        final PluggableAuthenticatorChain chain = new PluggableAuthenticatorChain(List.of(new TokenAAuthenticator("terminate", false)));
+        final TestTokenA token = new TestTokenA("err");
+        final Authenticator.Context context = createContext();
+        context.addAuthenticationToken(token);
+
+        Loggers.setLevel(LogManager.getLogger(PluggableAuthenticatorChain.class), Level.DEBUG);
+        try (MockLog mockLog = MockLog.capture(PluggableAuthenticatorChain.class)) {
+            mockLog.addExpectation(
+                new MockLog.SeenEventExpectation(
+                    "debug-auth-failure",
+                    PluggableAuthenticatorChain.class.getName(),
+                    Level.DEBUG,
+                    "Authentication of token [user-err] was terminated: token-a-fail-terminate-err (caused by: null)"
+                )
+            );
+
+            final PlainActionFuture<AuthenticationResult<Authentication>> future = new PlainActionFuture<>();
+            chain.authenticate(context, future);
+            mockLog.assertAllExpectationsMatched();
+
+            final ElasticsearchSecurityException ex = expectThrows(ElasticsearchSecurityException.class, () -> future.actionGet());
+            assertThat(ex, throwableWithMessage("mock-request-failure"));
+            assertThat(ex.status(), equalTo(RestStatus.UNAUTHORIZED));
+        }
+    }
+
     private Authenticator.Context createContext() {
-        return new Authenticator.Context(threadContext, null, null, true, null);
+        final var request = Mockito.mock(AuthenticationService.AuditableRequest.class);
+        Mockito.when(request.authenticationFailed(Mockito.any(AuthenticationToken.class)))
+            .thenAnswer(inv -> new ElasticsearchSecurityException("mock-request-failure", RestStatus.UNAUTHORIZED));
+        return new Authenticator.Context(threadContext, request, null, true, null);
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -23,6 +23,7 @@`
`23`	`23`	`import java.io.IOException;`
`24`	`24`	`import java.util.ArrayList;`
`25`	`25`	`import java.util.List;`
	`26`	`+import java.util.stream.Collectors;`
`26`	`27`
`27`	`28`	`/**`
`28`	`29`	`* The Authenticator interface represents an authentication mechanism or a group of similar authentication mechanisms.`
`@@ -241,5 +242,17 @@ public void addUnsuccessfulMessageToMetadata(final ElasticsearchSecurityExceptio`
`241`	`242`	`ese.addMetadata("es.additional_unsuccessful_credentials", getUnsuccessfulMessages());`
`242`	`243`	`}`
`243`	`244`	`}`
	`245`	`+`
	`246`	`+ @Override`
	`247`	`+ public String toString() {`
	`248`	`+ return Strings.format(`
	`249`	`+ "%s{tokens=%s, messages=%s}",`
	`250`	`+ getClass().getSimpleName(),`
	`251`	`+ this.authenticationTokens.stream()`
	`252`	`+ .map(t -> t.getClass().getSimpleName() + ":" + t.principal())`
	`253`	`+ .collect(Collectors.joining(",", "[", "]")),`
	`254`	`+ this.unsuccessfulMessages`
	`255`	`+ );`
	`256`	`+ }`
`244`	`257`	`}`
`245`	`258`	`}`