Skip to content

Commit

Permalink
Increase trace logging for native user auth (elastic#72065)
Browse files Browse the repository at this point in the history 
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)

Backport of: elastic#71991
  • Loading branch information
@tvernum
tvernum authored Apr 22, 2021
1 parent 617bf69 commit 06eceff
Show file tree
Hide file tree
Showing 4 changed files with 74 additions and 15 deletions.
3 changes: 3 additions & 0 deletions x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/user/User.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -129,6 +129,9 @@ public String toString() {
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("]");
}
Expand Down
38 changes: 30 additions & 8 deletions ...urity/src/main/java/org/elasticsearch/xpack/security/authc/esnative/NativeUsersStore.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -179,7 +179,7 @@ void getUserCount(final ActionListener<Long> listener) {
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);
Expand All @@ -192,15 +192,24 @@ private void getUserAndPassword(final String user, final ActionListener<UserAndP
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);
}
Expand Down Expand Up @@ -452,12 +461,25 @@ public void deleteUser(final DeleteUserRequest deleteUserRequest, final ActionLi
*/
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));
}
Expand Down
5 changes: 5 additions & 0 deletions ...curity/src/main/java/org/elasticsearch/xpack/security/authc/esnative/UserAndPassword.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -54,4 +54,9 @@ public int hashCode() {
result = 31 * result + passwordHash().hashCode();
return result;
}

@Override
public String toString() {
return "{" + user + " with password hashed with :" + (passwordHash == null ? "<null>" : hasher.name()) + "}";
}
}
43 changes: 36 additions & 7 deletions ...ain/java/org/elasticsearch/xpack/security/authc/support/CachingUsernamePasswordRealm.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -136,17 +136,22 @@ private void authenticateWithCache(UsernamePasswordToken token, ActionListener<A
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
Expand All @@ -157,18 +162,42 @@ private void authenticateWithCache(UsernamePasswordToken token, ActionListener<A
} 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
Expand Down

0 comments on commit 06eceff

Please sign in to comment.