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 98dad61ab1931..20289c5f09e91 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)); } } @@ -445,23 +458,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()); @@ -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> 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> 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> 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 { @@ -543,6 +564,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)))); @@ -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 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) {