Skip to content

Commit

Permalink
Add Debug/Trace logging for authentication (#49575)
Browse files Browse the repository at this point in the history 
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.

Relates: #49473
  • Loading branch information
@tvernum
tvernum committed Nov 27, 2019
1 parent 308ae98 commit df6e3fc
Show file tree
Hide file tree
Showing 3 changed files with 82 additions and 29 deletions.
18 changes: 18 additions & 0 deletions ...plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -207,6 +207,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;
Expand Down Expand Up @@ -262,6 +275,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 {
Expand Down
87 changes: 58 additions & 29 deletions .../security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticationService.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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();
Expand Down Expand Up @@ -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 -> {
Expand All @@ -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
Expand All @@ -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) {
Expand Down Expand Up @@ -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());
}

Expand All @@ -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;
}
Expand All @@ -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);
Expand All @@ -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) {
Expand All @@ -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 {
Expand All @@ -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));
}
}
Expand Down Expand Up @@ -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());
Expand All @@ -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
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand All @@ -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 {
Expand All @@ -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))));
Expand All @@ -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
Expand Down
6 changes: 6 additions & 0 deletions ...ugin/security/src/main/java/org/elasticsearch/xpack/security/rest/SecurityRestFilter.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down

0 comments on commit df6e3fc

Please sign in to comment.