From cb0bdc971c1d3227a210826434cd55fb7ceb228f Mon Sep 17 00:00:00 2001 From: Tim Vernum Date: Tue, 26 Nov 2019 16:02:58 +1100 Subject: [PATCH] Add Debug/Trace logging for authentication 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 --- .../core/security/authc/Authentication.java | 18 ++++ .../security/authc/AuthenticationService.java | 87 ++++++++++++------- .../security/rest/SecurityRestFilter.java | 6 ++ 3 files changed, 82 insertions(+), 29 deletions(-) diff --git a/x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java b/x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java index 17c3e05a772ce..f0a34e94655da 100644 --- a/x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java +++ b/x-pack/plugin/core/src/main/java/org/elasticsearch/xpack/core/security/authc/Authentication.java @@ -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; @@ -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 { diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticationService.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticationService.java index f5175b526be12..303bcd448331b 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/authc/AuthenticationService.java +++ b/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 authenticationListener) { createAuthenticator(request, authenticationListener).authenticateAsync(); @@ -128,12 +128,12 @@ public void authenticate(RestRequest request, ActionListener 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 listener) { createAuthenticator(action, message, fallbackUser, listener).authenticateAsync(); @@ -226,23 +226,25 @@ private Authenticator(AuditableRequest auditableRequest, User fallbackUser, Acti * these operations are: * *
    - *
  1. look for existing authentication {@link #lookForExistingAuthentication(Consumer)}
    2. - *
  2. look for a user token
    3. - *
  3. token extraction {@link #extractToken(Consumer)}
    4. - *
  4. token authentication {@link #consumeToken(AuthenticationToken)}
    5. - *
  5. user lookup for run as if necessary {@link #consumeUser(User, Map)} and - * {@link #lookupRunAsUser(User, String, Consumer)}
    6. - *
  6. write authentication into the context {@link #finishAuthentication(User)}
    7. + *
  7. look for existing authentication {@link #lookForExistingAuthentication(Consumer)}
    8. + *
  8. look for a user token
    9. + *
  9. token extraction {@link #extractToken(Consumer)}
    10. + *
  10. token authentication {@link #consumeToken(AuthenticationToken)}
    11. + *
  11. user lookup for run as if necessary {@link #consumeUser(User, Map)} and + * {@link #lookupRunAsUser(User, String, Consumer)}
    12. + *
  12. write authentication into the context {@link #finishAuthentication(User)}
    13. *
*/ 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 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 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 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> messages = new LinkedHashMap<>(); final BiConsumer> 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)); } } @@ -443,23 +456,25 @@ private List getRealmList(String principal) { * Handles failed extraction of an authentication token. This can happen in a few different scenarios: * *
    - *
  • this is an initial request from a client without preemptive authentication, so we must return an authentication - * challenge
    • - *
  • this is a request made internally within a node and there is a fallback user, which is typically the - * {@link SystemUser}
    • - *
  • anonymous access is enabled and this will be considered an anonymous request
    • + *
  • this is an initial request from a client without preemptive authentication, so we must return an authentication + * challenge
    • + *
  • this is a request made internally within a node and there is a fallback user, which is typically the + * {@link SystemUser}
    • + *
  • anonymous access is enabled and this will be considered an anonymous request
    • *
- * + *

* 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()); @@ -471,7 +486,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 @@ -499,6 +517,7 @@ private void consumeUser(User user, Map> 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); @@ -512,7 +531,7 @@ private void consumeUser(User user, Map> 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); @@ -526,10 +545,12 @@ private void consumeUser(User user, Map> message * names of users that exist using a timing attack */ private void lookupRunAsUser(final User user, String runAsUsername, Consumer 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 { @@ -541,6 +562,7 @@ private void lookupRunAsUser(final User user, String runAsUsername, Consumer 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)))); @@ -567,11 +589,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 diff --git a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/rest/SecurityRestFilter.java b/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/rest/SecurityRestFilter.java index 6a5f49545933f..df678f9c63ba4 100644 --- a/x-pack/plugin/security/src/main/java/org/elasticsearch/xpack/security/rest/SecurityRestFilter.java +++ b/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) {