Increase trace logging for native user auth (#71991)

This change adds new DEBUG and TRACE logs for native user
authentication (and, by consequence other password based realms such
as the reserved realm and LDAP realms)

x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/user/User.java

@@ -128,6 +128,9 @@ public class User implements ToXContentObject {
         sb.append(",email=").append(email);
         sb.append(",metadata=");
         sb.append(metadata);
+        if (enabled == false) {
+            sb.append(",(disabled)");
+        }
         if (authenticatedUser != null) {
             sb.append(",authenticatedUser=[").append(authenticatedUser.toString()).append("]");
         }

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

@@ -178,7 +178,7 @@ public class NativeUsersStore {
     private void getUserAndPassword(final String user, final ActionListener<UserAndPassword> listener) {
         final SecurityIndexManager frozenSecurityIndex = securityIndex.freeze();
         if (frozenSecurityIndex.isAvailable() == false) {
-            if (frozenSecurityIndex.indexExists()) {
+            if (frozenSecurityIndex.indexExists() == false) {
                 logger.trace("could not retrieve user [{}] because security index does not exist", user);
             } else {
                 logger.error("security index is unavailable. short circuiting retrieval of user [{}]", user);
@@ -191,15 +191,24 @@ public class NativeUsersStore {
                             new ActionListener<GetResponse>() {
                                 @Override
                                 public void onResponse(GetResponse response) {
+                                    logger.trace(
+                                        "user [{}] is doc [{}] in index [{}] with primTerm [{}] and seqNo [{}]",
+                                        user,
+                                        response.getId(),
+                                        response.getIndex(),
+                                        response.getPrimaryTerm(),
+                                        response.getSeqNo()
+                                    );
                                     listener.onResponse(transformUser(response.getId(), response.getSource()));
                                 }
 
                                 @Override
                                 public void onFailure(Exception t) {
                                     if (t instanceof IndexNotFoundException) {
-                                        logger.trace(
-                                                (org.apache.logging.log4j.util.Supplier<?>) () -> new ParameterizedMessage(
-                                                        "could not retrieve user [{}] because security index does not exist", user), t);
+                                        logger.trace(new ParameterizedMessage(
+                                                "could not retrieve user [{}] because security index does not exist",
+                                                user),
+                                            t);
                                     } else {
                                         logger.error(new ParameterizedMessage("failed to retrieve user [{}]", user), t);
                                     }
@@ -451,12 +460,25 @@ public class NativeUsersStore {
      */
     void verifyPassword(String username, final SecureString password, ActionListener<AuthenticationResult> listener) {
         getUserAndPassword(username, ActionListener.wrap((userAndPassword) -> {
-            if (userAndPassword == null || userAndPassword.passwordHash() == null) {
+            if (userAndPassword == null) {
+                logger.trace(
+                    "user [{}] does not exist in index [{}], cannot authenticate against the native realm",
+                    username,
+                    securityIndex.aliasName()
+                );
+                listener.onResponse(AuthenticationResult.notHandled());
+            } else if (userAndPassword.passwordHash() == null) {
+                logger.debug("user [{}] in index [{}] does not have a password, cannot authenticate", username, securityIndex.aliasName());
                 listener.onResponse(AuthenticationResult.notHandled());
-            } else if (userAndPassword.verifyPassword(password)) {
-                listener.onResponse(AuthenticationResult.success(userAndPassword.user()));
             } else {
-                listener.onResponse(AuthenticationResult.unsuccessful("Password authentication failed for " + username, null));
+                if (userAndPassword.verifyPassword(password)) {
+                    logger.trace(
+                        "successfully authenticated user [{}] (security index [{}])", userAndPassword, securityIndex.aliasName());
+                    listener.onResponse(AuthenticationResult.success(userAndPassword.user()));
+                } else {
+                    logger.trace("password mismatch for user [{}] (security index [{}])", userAndPassword, securityIndex.aliasName());
+                    listener.onResponse(AuthenticationResult.unsuccessful("Password authentication failed for " + username, null));
+                }
             }
         }, listener::onFailure));
     }

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

@@ -54,4 +54,9 @@ class UserAndPassword {
         result = 31 * result + passwordHash().hashCode();
         return result;
     }
+
+    @Override
+    public String toString() {
+        return "{" + user + " with password hashed with :" + (passwordHash == null ? "<null>" : hasher.name()) + "}";
+    }
 }

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

@@ -136,17 +136,22 @@ public abstract class CachingUsernamePasswordRealm extends UsernamePasswordRealm
                     if (cachedResult.authenticationResult.isAuthenticated()) {
                         if (credsMatch) {
                             // cached credential hash matches the credential hash for this forestalled request
-                            handleCachedAuthentication(cachedResult.user, ActionListener.wrap(cacheResult -> {
-                                if (cacheResult.isAuthenticated()) {
-                                    logger.debug("realm [{}] authenticated user [{}], with roles [{}]",
-                                        name(), token.principal(), cacheResult.getUser().roles());
+                            handleCachedAuthentication(cachedResult.user, ActionListener.wrap(authResult -> {
+                                if (authResult.isAuthenticated()) {
+                                    logger.debug("realm [{}] authenticated user [{}], with roles [{}] (cached)",
+                                        name(), token.principal(), authResult.getUser().roles());
                                 } else {
                                     logger.debug("realm [{}] authenticated user [{}] from cache, but then failed [{}]",
-                                        name(), token.principal(), cacheResult.getMessage());
+                                        name(), token.principal(), authResult.getMessage());
                                 }
-                                listener.onResponse(cacheResult);
+                                listener.onResponse(authResult);
                             }, listener::onFailure));
                         } else {
+                            logger.trace(
+                                "realm [{}], provided credentials for user [{}] do not match (known good) cached credentials," +
+                                    " invalidating cache and retrying",
+                                name(), token.principal()
+                            );
                             // its credential hash does not match the
                             // hash of the credential for this forestalled request.
                             // clear cache and try to reach the authentication source again because password
@@ -157,18 +162,42 @@ public abstract class CachingUsernamePasswordRealm extends UsernamePasswordRealm
                     } else if (credsMatch) {
                         // not authenticated but instead of hammering reuse the result. a new
                         // request will trigger a retried auth
+                        logger.trace(
+                            "realm [{}], provided credentials for user [{}] are invalid (cached result) status:[{}] message:[{}]",
+                            name(),
+                            token.principal(),
+                            cachedResult.authenticationResult.getStatus(),
+                            cachedResult.authenticationResult.getMessage()
+                        );
                         listener.onResponse(cachedResult.authenticationResult);
                     } else {
+                        logger.trace(
+                            "realm [{}], provided credentials for user [{}] do not match (possibly invalid) cached credentials," +
+                                " invalidating cache and retrying",
+                            name(),
+                            token.principal()
+                        );
                         cache.invalidate(token.principal(), listenableCacheEntry);
                         authenticateWithCache(token, listener);
                     }
                 }, listener::onFailure), threadPool.executor(ThreadPool.Names.GENERIC), threadPool.getThreadContext());
             } else {
+                logger.trace(
+                    "realm [{}] does not have a cached result for user [{}]; attempting fresh authentication", name(), token.principal());
                 // attempt authentication against the authentication source
                 doAuthenticate(token, ActionListener.wrap(authResult -> {
-                    if (authResult.isAuthenticated() == false || authResult.getUser().enabled() == false) {
+                    if (authResult.isAuthenticated() == false) {
+                        logger.trace("realm [{}] did not authenticate user [{}] ([{}])", name(), token.principal(), authResult);
                         // a new request should trigger a new authentication
                         cache.invalidate(token.principal(), listenableCacheEntry);
+                    } else if (authResult.getUser().enabled() == false) {
+                        logger.debug(
+                            "realm [{}] cannot authenticate [{}], user is not enabled ([{}])",
+                            name(), token.principal(), authResult.getUser());
+                        // a new request should trigger a new authentication
+                        cache.invalidate(token.principal(), listenableCacheEntry);
+                    } else {
+                        logger.debug("realm [{}], successful authentication [{}] for [{}]", name(), authResult, token.principal());
                     }
                     // notify any forestalled request listeners; they will not reach to the
                     // authentication request and instead will use this result if they contain