Add Debug/Trace logging for authentication (#49619)

Authentication has grown more complex with the addition of new realm
types and authentication methods. When user authentication does not
behave as expected it can be difficult to determine where and why it
failed.

This commit adds DEBUG and TRACE logging at key points in the
authentication flow so that it is possible to gain addition insight
into the operation of the system.

Backport of: #49575

Author: tvernum

x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java

@@ -214,6 +214,19 @@ public XContentBuilder toXContent(XContentBuilder builder, Params params) throws
         return builder.endObject();
     }
 
+    @Override
+    public String toString() {
+        StringBuilder builder = new StringBuilder("Authentication[")
+            .append(user)
+            .append(",type=").append(type)
+            .append(",by=").append(authenticatedBy);
+        if (lookedUpBy != null) {
+            builder.append(",lookup=").append(lookedUpBy);
+        }
+        builder.append("]");
+        return builder.toString();
+    }
+
     public static class RealmRef {
 
         private final String nodeName;
@@ -269,6 +282,11 @@ public int hashCode() {
             result = 31 * result + type.hashCode();
             return result;
         }
+
+        @Override
+        public String toString() {
+            return "{Realm[" + type + "." + name + "] on Node[" + nodeName + "]}";
+        }
     }
 
     public enum AuthenticationType {

x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticationService.java

@@ -116,7 +116,7 @@ public AuthenticationService(Settings settings, Realms realms, AuditTrailService
      * a user was indeed associated with the request and the credentials were verified to be valid), the method returns
      * the user and that user is then "attached" to the request's context.
      *
-     * @param request   The request to be authenticated
+     * @param request The request to be authenticated
      */
     public void authenticate(RestRequest request, ActionListener<Authentication> authenticationListener) {
         createAuthenticator(request, authenticationListener).authenticateAsync();
@@ -128,12 +128,12 @@ public void authenticate(RestRequest request, ActionListener<Authentication> aut
      * the user and that user is then "attached" to the message's context. If no user was found to be attached to the given
      * message, then the given fallback user will be returned instead.
      *
-     * @param action        The action of the message
-     * @param message       The message to be authenticated
-     * @param fallbackUser  The default user that will be assumed if no other user is attached to the message. Can be
-     *                      {@code null}, in which case there will be no fallback user and the success/failure of the
-     *                      authentication will be based on the whether there's an attached user to in the message and
-     *                      if there is, whether its credentials are valid.
+     * @param action       The action of the message
+     * @param message      The message to be authenticated
+     * @param fallbackUser The default user that will be assumed if no other user is attached to the message. Can be
+     *                     {@code null}, in which case there will be no fallback user and the success/failure of the
+     *                     authentication will be based on the whether there's an attached user to in the message and
+     *                     if there is, whether its credentials are valid.
      */
     public void authenticate(String action, TransportMessage message, User fallbackUser, ActionListener<Authentication> listener) {
         createAuthenticator(action, message, fallbackUser, listener).authenticateAsync();
@@ -226,23 +226,25 @@ private Authenticator(AuditableRequest auditableRequest, User fallbackUser, Acti
          * these operations are:
          *
          * <ol>
-         *     <li>look for existing authentication {@link #lookForExistingAuthentication(Consumer)}</li>
-         *     <li>look for a user token</li>
-         *     <li>token extraction {@link #extractToken(Consumer)}</li>
-         *     <li>token authentication {@link #consumeToken(AuthenticationToken)}</li>
-         *     <li>user lookup for run as if necessary {@link #consumeUser(User, Map)} and
-         *     {@link #lookupRunAsUser(User, String, Consumer)}</li>
-         *     <li>write authentication into the context {@link #finishAuthentication(User)}</li>
+         * <li>look for existing authentication {@link #lookForExistingAuthentication(Consumer)}</li>
+         * <li>look for a user token</li>
+         * <li>token extraction {@link #extractToken(Consumer)}</li>
+         * <li>token authentication {@link #consumeToken(AuthenticationToken)}</li>
+         * <li>user lookup for run as if necessary {@link #consumeUser(User, Map)} and
+         * {@link #lookupRunAsUser(User, String, Consumer)}</li>
+         * <li>write authentication into the context {@link #finishAuthentication(User)}</li>
          * </ol>
          */
         private void authenticateAsync() {
             if (defaultOrderedRealmList.isEmpty()) {
                 // this happens when the license state changes between the call to authenticate and the actual invocation
                 // to get the realm list
+                logger.debug("No realms available, failing authentication");
                 listener.onResponse(null);
             } else {
                 lookForExistingAuthentication((authentication) -> {
                     if (authentication != null) {
+                        logger.trace("Found existing authentication [{}] in request [{}]", authentication, request);
                         listener.onResponse(authentication);
                     } else {
                         tokenService.getAndValidateToken(threadContext, ActionListener.wrap(userToken -> {
@@ -252,6 +254,7 @@ private void authenticateAsync() {
                                 checkForApiKey();
                             }
                         }, e -> {
+                            logger.debug(new ParameterizedMessage("Failed to validate token authentication for request [{}]", request), e);
                             if (e instanceof ElasticsearchSecurityException &&
                                 tokenService.isExpiredTokenException((ElasticsearchSecurityException) e) == false) {
                                 // intentionally ignore the returned exception; we call this primarily
@@ -275,6 +278,7 @@ private void checkForApiKey() {
                     } else if (authResult.getStatus() == AuthenticationResult.Status.TERMINATE) {
                         Exception e = (authResult.getException() != null) ? authResult.getException()
                             : Exceptions.authenticationError(authResult.getMessage());
+                        logger.debug(new ParameterizedMessage("API key service terminated authentication for request [{}]", request), e);
                         listener.onFailure(e);
                     } else {
                         if (authResult.getMessage() != null) {
@@ -308,7 +312,7 @@ private void lookForExistingAuthentication(Consumer<Authentication> authenticati
             } catch (Exception e) {
                 logger.error((Supplier<?>)
                         () -> new ParameterizedMessage("caught exception while trying to read authentication from request [{}]", request),
-                        e);
+                    e);
                 action = () -> listener.onFailure(request.tamperedRequest());
             }
 
@@ -332,6 +336,8 @@ void extractToken(Consumer<AuthenticationToken> consumer) {
                     for (Realm realm : defaultOrderedRealmList) {
                         final AuthenticationToken token = realm.token(threadContext);
                         if (token != null) {
+                            logger.trace("Found authentication credentials [{}] for principal [{}] in request [{}]",
+                                token.getClass().getName(), token.principal(), request);
                             action = () -> consumer.accept(token);
                             break;
                         }
@@ -358,12 +364,17 @@ private void consumeToken(AuthenticationToken token) {
             } else {
                 authenticationToken = token;
                 final List<Realm> realmsList = getRealmList(authenticationToken.principal());
+                logger.trace("Checking token of type [{}] against [{}] realm(s)", token.getClass().getName(), realmsList.size());
                 final long startInvalidation = numInvalidation.get();
                 final Map<Realm, Tuple<String, Exception>> messages = new LinkedHashMap<>();
                 final BiConsumer<Realm, ActionListener<User>> realmAuthenticatingConsumer = (realm, userListener) -> {
                     if (realm.supports(authenticationToken)) {
+                        logger.trace("Trying to authenticate [{}] using realm [{}] with token [{}] ",
+                            token.principal(), realm, token.getClass().getName());
                         realm.authenticate(authenticationToken, ActionListener.wrap((result) -> {
                             assert result != null : "Realm " + realm + " produced a null authentication result";
+                            logger.debug("Authentication of [{}] using realm [{}] with token [{}] was [{}]",
+                                token.principal(), realm, token.getClass().getSimpleName(), result);
                             if (result.getStatus() == AuthenticationResult.Status.SUCCESS) {
                                 // user was authenticated, populate the authenticated by information
                                 authenticatedBy = new RealmRef(realm.name(), realm.type(), nodeName);
@@ -377,9 +388,9 @@ private void consumeToken(AuthenticationToken token) {
                                 request.realmAuthenticationFailed(authenticationToken, realm.name());
                                 if (result.getStatus() == AuthenticationResult.Status.TERMINATE) {
                                     logger.info("Authentication of [{}] was terminated by realm [{}] - {}",
-                                            authenticationToken.principal(), realm.name(), result.getMessage());
+                                        authenticationToken.principal(), realm.name(), result.getMessage());
                                     Exception e = (result.getException() != null) ? result.getException()
-                                            : Exceptions.authenticationError(result.getMessage());
+                                        : Exceptions.authenticationError(result.getMessage());
                                     userListener.onFailure(e);
                                 } else {
                                     if (result.getMessage() != null) {
@@ -390,8 +401,8 @@ private void consumeToken(AuthenticationToken token) {
                             }
                         }, (ex) -> {
                             logger.warn(new ParameterizedMessage(
-                                    "An error occurred while attempting to authenticate [{}] against realm [{}]",
-                                    authenticationToken.principal(), realm.name()), ex);
+                                "An error occurred while attempting to authenticate [{}] against realm [{}]",
+                                authenticationToken.principal(), realm.name()), ex);
                             userListener.onFailure(ex);
                         }));
                     } else {
@@ -407,6 +418,8 @@ private void consumeToken(AuthenticationToken token) {
                 try {
                     authenticatingListener.run();
                 } catch (Exception e) {
+                    logger.debug(new ParameterizedMessage("Authentication of [{}] with token [{}] failed",
+                        token.principal(), token.getClass().getName()), e);
                     listener.onFailure(request.exceptionProcessingRequest(e, token));
                 }
             }
@@ -445,23 +458,25 @@ private List<Realm> getRealmList(String principal) {
          * Handles failed extraction of an authentication token. This can happen in a few different scenarios:
          *
          * <ul>
-         *     <li>this is an initial request from a client without preemptive authentication, so we must return an authentication
-         *     challenge</li>
-         *     <li>this is a request made internally within a node and there is a fallback user, which is typically the
-         *     {@link SystemUser}</li>
-         *     <li>anonymous access is enabled and this will be considered an anonymous request</li>
+         * <li>this is an initial request from a client without preemptive authentication, so we must return an authentication
+         * challenge</li>
+         * <li>this is a request made internally within a node and there is a fallback user, which is typically the
+         * {@link SystemUser}</li>
+         * <li>anonymous access is enabled and this will be considered an anonymous request</li>
          * </ul>
-         *
+         * <p>
          * Regardless of the scenario, this method will call the listener with either failure or success.
          */
         // pkg-private for tests
         void handleNullToken() {
             final Authentication authentication;
             if (fallbackUser != null) {
+                logger.trace("No valid credentials found in request [{}], using fallback [{}]", request, fallbackUser.principal());
                 RealmRef authenticatedBy = new RealmRef("__fallback", "__fallback", nodeName);
                 authentication = new Authentication(fallbackUser, authenticatedBy, null, Version.CURRENT, AuthenticationType.INTERNAL,
                     Collections.emptyMap());
             } else if (isAnonymousUserEnabled) {
+                logger.trace("No valid credentials found in request [{}], using anonymous [{}]", request, anonymousUser.principal());
                 RealmRef authenticatedBy = new RealmRef("__anonymous", "__anonymous", nodeName);
                 authentication = new Authentication(anonymousUser, authenticatedBy, null, Version.CURRENT, AuthenticationType.ANONYMOUS,
                     Collections.emptyMap());
@@ -473,7 +488,10 @@ void handleNullToken() {
             if (authentication != null) {
                 action = () -> writeAuthToContext(authentication);
             } else {
-                action = () -> listener.onFailure(request.anonymousAccessDenied());
+                action = () -> {
+                    logger.debug("No valid credentials found in request [{}], rejecting", request);
+                    listener.onFailure(request.anonymousAccessDenied());
+                };
             }
 
             // we assign the listener call to an action to avoid calling the listener within a try block and auditing the wrong thing when
@@ -501,6 +519,7 @@ private void consumeUser(User user, Map<Realm, Tuple<String, Exception>> message
                         Strings.collectionToCommaDelimitedString(defaultOrderedRealmList),
                         Strings.collectionToCommaDelimitedString(unlicensedRealms));
                 }
+                logger.trace("Failed to authenticate request [{}]", request);
                 listener.onFailure(request.authenticationFailed(authenticationToken));
             } else {
                 threadContext.putTransient(AuthenticationResult.THREAD_CONTEXT_KEY, authenticationResult);
@@ -514,7 +533,7 @@ private void consumeUser(User user, Map<Realm, Tuple<String, Exception>> message
                         assert runAsUsername.isEmpty() : "the run as username may not be empty";
                         logger.debug("user [{}] attempted to runAs with an empty username", user.principal());
                         listener.onFailure(request.runAsDenied(
-                                new Authentication(new User(runAsUsername, null, user), authenticatedBy, lookedupBy), authenticationToken));
+                            new Authentication(new User(runAsUsername, null, user), authenticatedBy, lookedupBy), authenticationToken));
                     }
                 } else {
                     finishAuthentication(user);
@@ -528,10 +547,12 @@ private void consumeUser(User user, Map<Realm, Tuple<String, Exception>> message
          * names of users that exist using a timing attack
          */
         private void lookupRunAsUser(final User user, String runAsUsername, Consumer<User> userConsumer) {
+            logger.trace("Looking up run-as user [{}] for authenticated user [{}]", runAsUsername, user.principal());
             final RealmUserLookup lookup = new RealmUserLookup(getRealmList(runAsUsername), threadContext);
             final long startInvalidationNum = numInvalidation.get();
             lookup.lookup(runAsUsername, ActionListener.wrap(tuple -> {
                 if (tuple == null) {
+                    logger.debug("Cannot find run-as user [{}] for authenticated user [{}]", runAsUsername, user.principal());
                     // the user does not exist, but we still create a User object, which will later be rejected by authz
                     userConsumer.accept(new User(runAsUsername, null, user));
                 } else {
@@ -543,6 +564,7 @@ private void lookupRunAsUser(final User user, String runAsUsername, Consumer<Use
                         // this might provide a valid hint
                         lastSuccessfulAuthCache.computeIfAbsent(runAsUsername, s -> realm);
                     }
+                    logger.trace("Using run-as user [{}] with authenticated user [{}]", foundUser, user.principal());
                     userConsumer.accept(new User(foundUser, user));
                 }
             }, exception -> listener.onFailure(request.exceptionProcessingRequest(exception, authenticationToken))));
@@ -569,11 +591,18 @@ void finishAuthentication(User finalUser) {
          */
         void writeAuthToContext(Authentication authentication) {
             request.authenticationSuccess(authentication.getAuthenticatedBy().getName(), authentication.getUser());
-            Runnable action = () -> listener.onResponse(authentication);
+            Runnable action = () -> {
+                logger.trace("Established authentication [{}] for request [{}]", authentication, request);
+                listener.onResponse(authentication);
+            };
             try {
                 authentication.writeToContext(threadContext);
             } catch (Exception e) {
-                action = () -> listener.onFailure(request.exceptionProcessingRequest(e, authenticationToken));
+                action = () -> {
+                    logger.debug(
+                        new ParameterizedMessage("Failed to store authentication [{}] for request [{}]", authentication, request), e);
+                    listener.onFailure(request.exceptionProcessingRequest(e, authenticationToken));
+                };
             }
 
             // we assign the listener call to an action to avoid calling the listener within a try block and auditing the wrong thing

x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/rest/SecurityRestFilter.java

@@ -54,9 +54,15 @@ public void handleRequest(RestRequest request, RestChannel channel, NodeClient c
             }
             service.authenticate(maybeWrapRestRequest(request), ActionListener.wrap(
                 authentication -> {
+                    if (authentication == null) {
+                        logger.trace("No authentication available for REST request [{}]", request.uri());
+                    } else {
+                        logger.trace("Authenticated REST request [{}] as {}", request.uri(), authentication);
+                    }
                     RemoteHostHeader.process(request, threadContext);
                     restHandler.handleRequest(request, channel, client);
                 }, e -> {
+                    logger.debug(new ParameterizedMessage("Authentication failed for REST request [{}]", request.uri()), e);
                     try {
                         channel.sendResponse(new BytesRestResponse(channel, e));
                     } catch (Exception inner) {