Additional DEBUG logging on authc failures

docs/changelog/137941.yaml

@@ -0,0 +1,5 @@
+pr: 137941
+summary: Additional DEBUG logging on authc failures
+area: Authentication
+type: enhancement
+issues: []

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
+            );
+        }
     }
 }

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);

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 {

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")

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);
     }
 }