From 0202480742b8539aa7aa1e94dc9cab75d863cc4e Mon Sep 17 00:00:00 2001 From: Xiao Chen Date: Thu, 8 Jun 2017 21:27:06 -0700 Subject: [PATCH] HADOOP-13174. Add more debug logs for delegation tokens and authentication. --- .../authentication/client/AuthenticatedURL.java | 8 ++++++++ .../authentication/server/AuthenticationFilter.java | 12 ++++++++++-- .../server/TestAuthenticationFilter.java | 1 + .../hadoop/crypto/key/kms/KMSClientProvider.java | 10 ++++++++++ .../AbstractDelegationTokenSecretManager.java | 1 + .../web/DelegationTokenAuthenticatedURL.java | 11 +++++++++++ .../web/DelegationTokenAuthenticationHandler.java | 8 ++++++++ .../delegation/web/DelegationTokenAuthenticator.java | 11 +++++++++++ 8 files changed, 60 insertions(+), 2 deletions(-) diff --git a/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/client/AuthenticatedURL.java b/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/client/AuthenticatedURL.java index 6604c3ffc1..5696ba0bd8 100644 --- a/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/client/AuthenticatedURL.java +++ b/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/client/AuthenticatedURL.java @@ -14,6 +14,8 @@ package org.apache.hadoop.security.authentication.client; import org.apache.hadoop.security.authentication.server.AuthenticationFilter; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.FileNotFoundException; import java.io.IOException; @@ -59,6 +61,8 @@ * */ public class AuthenticatedURL { + private static final Logger LOG = + LoggerFactory.getLogger(AuthenticatedURL.class); /** * Name of the HTTP cookie used for the authentication token between the client and the server. @@ -265,15 +269,19 @@ public static void extractToken(HttpURLConnection conn, Token token) throws IOEx value = value.substring(0, separator); } if (value.length() > 0) { + LOG.trace("Setting token value to {} ({}), resp={}", value, + token, respCode); token.set(value); } } } } } else if (respCode == HttpURLConnection.HTTP_NOT_FOUND) { + LOG.trace("Setting token value to null ({}), resp={}", token, respCode); token.set(null); throw new FileNotFoundException(conn.getURL().toString()); } else { + LOG.trace("Setting token value to null ({}), resp={}", token, respCode); token.set(null); throw new AuthenticationException("Authentication failed" + ", URL: " + conn.getURL() + diff --git a/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/server/AuthenticationFilter.java b/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/server/AuthenticationFilter.java index b10fc844bb..5aeddac26d 100644 --- a/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/server/AuthenticationFilter.java +++ b/hadoop-common-project/hadoop-auth/src/main/java/org/apache/hadoop/security/authentication/server/AuthenticationFilter.java @@ -516,6 +516,10 @@ public void doFilter(ServletRequest request, AuthenticationToken token; try { token = getToken(httpRequest); + if (LOG.isDebugEnabled()) { + LOG.debug("Got token {} from httpRequest {}", token, + getRequestURL(httpRequest)); + } } catch (AuthenticationException ex) { LOG.warn("AuthenticationToken ignored: " + ex.getMessage()); @@ -526,8 +530,8 @@ public void doFilter(ServletRequest request, if (authHandler.managementOperation(token, httpRequest, httpResponse)) { if (token == null) { if (LOG.isDebugEnabled()) { - LOG.debug("Request [{}] triggering authentication", - getRequestURL(httpRequest)); + LOG.debug("Request [{}] triggering authentication. handler: {}", + getRequestURL(httpRequest), authHandler.getClass()); } token = authHandler.authenticate(httpRequest, httpResponse); if (token != null && token != AuthenticationToken.ANONYMOUS) { @@ -588,6 +592,10 @@ && getMaxInactiveInterval() > 0) { doFilter(filterChain, httpRequest, httpResponse); } } else { + if (LOG.isDebugEnabled()) { + LOG.debug("managementOperation returned false for request {}." + + " token: {}", getRequestURL(httpRequest), token); + } unauthorizedResponse = false; } } catch (AuthenticationException ex) { diff --git a/hadoop-common-project/hadoop-auth/src/test/java/org/apache/hadoop/security/authentication/server/TestAuthenticationFilter.java b/hadoop-common-project/hadoop-auth/src/test/java/org/apache/hadoop/security/authentication/server/TestAuthenticationFilter.java index 88702d94fb..87223d157d 100644 --- a/hadoop-common-project/hadoop-auth/src/test/java/org/apache/hadoop/security/authentication/server/TestAuthenticationFilter.java +++ b/hadoop-common-project/hadoop-auth/src/test/java/org/apache/hadoop/security/authentication/server/TestAuthenticationFilter.java @@ -1232,6 +1232,7 @@ public void testManagementOperation() throws Exception { String tokenSigned = signer.sign(token.toString()); Cookie cookie = new Cookie(AuthenticatedURL.AUTH_COOKIE, tokenSigned); Mockito.when(request.getCookies()).thenReturn(new Cookie[]{cookie}); + Mockito.when(request.getRequestURL()).thenReturn(new StringBuffer()); filter.doFilter(request, response, chain); diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/crypto/key/kms/KMSClientProvider.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/crypto/key/kms/KMSClientProvider.java index 098821a908..b3abd0c5ce 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/crypto/key/kms/KMSClientProvider.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/crypto/key/kms/KMSClientProvider.java @@ -590,6 +590,10 @@ private T call(HttpURLConnection conn, Map jsonOutput, // failure. Unfortunately, the AuthenticationFilter returns 403 when it // cannot authenticate (Since a 401 requires Server to send // WWW-Authenticate header as well).. + if (LOG.isDebugEnabled()) { + LOG.debug("Response={}({}), resetting authToken", + conn.getResponseCode(), conn.getResponseMessage()); + } KMSClientProvider.this.authToken = new DelegationTokenAuthenticatedURL.Token(); if (authRetryCount > 0) { @@ -604,6 +608,10 @@ private T call(HttpURLConnection conn, Map jsonOutput, } try { AuthenticatedURL.extractToken(conn, authToken); + if (LOG.isDebugEnabled()) { + LOG.debug("Extracted token, authToken={}, its dt={}", authToken, + authToken.getDelegationToken()); + } } catch (AuthenticationException e) { // Ignore the AuthExceptions.. since we are just using the method to // extract and set the authToken.. (Workaround till we actually fix @@ -1055,11 +1063,13 @@ public Token[] addDelegationTokens(final String renewer, public Token run() throws Exception { // Not using the cached token here.. Creating a new token here // everytime. + LOG.debug("Getting new token from {}, renewer:{}", url, renewer); return authUrl.getDelegationToken(url, new DelegationTokenAuthenticatedURL.Token(), renewer, doAsUser); } }); if (token != null) { + LOG.debug("New token received: ({})", token); credentials.addToken(token.getService(), token); tokens = new Token[] { token }; } else { diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/AbstractDelegationTokenSecretManager.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/AbstractDelegationTokenSecretManager.java index 4b14059821..cf88745032 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/AbstractDelegationTokenSecretManager.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/AbstractDelegationTokenSecretManager.java @@ -629,6 +629,7 @@ private void removeExpiredToken() throws IOException { // don't hold lock on 'this' to avoid edit log updates blocking token ops for (TokenIdent ident : expiredTokens) { logExpireToken(ident); + LOG.info("Removing expired token " + formatTokenId(ident)); removeStoredToken(ident); } } diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticatedURL.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticatedURL.java index 4dedf92f5b..0b1fdf80c9 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticatedURL.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticatedURL.java @@ -29,6 +29,8 @@ import org.apache.hadoop.security.authentication.client.ConnectionConfigurator; import org.apache.hadoop.security.token.TokenIdentifier; import org.apache.hadoop.security.token.delegation.AbstractDelegationTokenIdentifier; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import java.io.IOException; import java.net.HttpURLConnection; @@ -61,6 +63,9 @@ @InterfaceStability.Unstable public class DelegationTokenAuthenticatedURL extends AuthenticatedURL { + private static final Logger LOG = + LoggerFactory.getLogger(DelegationTokenAuthenticatedURL.class); + /** * Constant used in URL's query string to perform a proxy user request, the * value of the DO_AS parameter is the user the request will be @@ -283,17 +288,23 @@ public HttpURLConnection openConnection(URL url, Token token, String doAs) Map extraParams = new HashMap(); org.apache.hadoop.security.token.Token dToken = null; + LOG.debug("Connecting to url {} with token {} as {}", url, token, doAs); // if we have valid auth token, it takes precedence over a delegation token // and we don't even look for one. if (!token.isSet()) { // delegation token Credentials creds = UserGroupInformation.getCurrentUser(). getCredentials(); + if (LOG.isDebugEnabled()) { + LOG.debug("Token not set, looking for delegation token. Creds:{}", + creds.getAllTokens()); + } if (!creds.getAllTokens().isEmpty()) { InetSocketAddress serviceAddr = new InetSocketAddress(url.getHost(), url.getPort()); Text service = SecurityUtil.buildTokenService(serviceAddr); dToken = creds.getToken(service); + LOG.debug("Using delegation token {} from service:{}", dToken, service); if (dToken != null) { if (useQueryStringForDelegationToken()) { // delegation token will go in the query string, injecting it diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticationHandler.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticationHandler.java index e8bf7f764f..106c6be8fe 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticationHandler.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticationHandler.java @@ -48,6 +48,8 @@ import org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager; import org.apache.hadoop.util.HttpExceptionUtils; import org.apache.hadoop.util.StringUtils; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import com.fasterxml.jackson.core.JsonFactory; import com.fasterxml.jackson.core.JsonGenerator; @@ -79,6 +81,8 @@ @InterfaceStability.Evolving public abstract class DelegationTokenAuthenticationHandler implements AuthenticationHandler { + private static final Logger LOG = + LoggerFactory.getLogger(DelegationTokenAuthenticationHandler.class); protected static final String TYPE_POSTFIX = "-dt"; @@ -220,6 +224,7 @@ public boolean managementOperation(AuthenticationToken token, HttpServletRequest request, HttpServletResponse response) throws IOException, AuthenticationException { boolean requestContinues = true; + LOG.trace("Processing operation for req=({}), token: {}", request, token); String op = ServletUtils.getParameter(request, KerberosDelegationTokenAuthenticator.OP_PARAM); op = (op != null) ? StringUtils.toUpperCase(op) : null; @@ -232,6 +237,7 @@ public boolean managementOperation(AuthenticationToken token, if (dtOp.requiresKerberosCredentials() && token == null) { // Don't authenticate via DT for DT ops. token = authHandler.authenticate(request, response); + LOG.trace("Got token: {}.", token); if (token == null) { requestContinues = false; doManagement = false; @@ -380,6 +386,7 @@ public AuthenticationToken authenticate(HttpServletRequest request, AuthenticationToken token; String delegationParam = getDelegationToken(request); if (delegationParam != null) { + LOG.debug("Authenticating with dt param: {}", delegationParam); try { Token dt = new Token(); dt.decodeFromUrlString(delegationParam); @@ -397,6 +404,7 @@ public AuthenticationToken authenticate(HttpServletRequest request, HttpServletResponse.SC_FORBIDDEN, new AuthenticationException(ex)); } } else { + LOG.debug("Falling back to {} (req={})", authHandler.getClass(), request); token = authHandler.authenticate(request, response); } return token; diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticator.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticator.java index 87a569706c..06932ac623 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticator.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticator.java @@ -115,10 +115,16 @@ private boolean hasDelegationToken(URL url, AuthenticatedURL.Token token) { if (token instanceof DelegationTokenAuthenticatedURL.Token) { hasDt = ((DelegationTokenAuthenticatedURL.Token) token). getDelegationToken() != null; + if (hasDt) { + LOG.trace("Delegation token found: {}", + ((DelegationTokenAuthenticatedURL.Token) token) + .getDelegationToken()); + } } if (!hasDt) { String queryStr = url.getQuery(); hasDt = (queryStr != null) && queryStr.contains(DELEGATION_PARAM + "="); + LOG.trace("hasDt={}, queryStr={}", hasDt, queryStr); } return hasDt; } @@ -129,7 +135,12 @@ public void authenticate(URL url, AuthenticatedURL.Token token) if (!hasDelegationToken(url, token)) { // check and renew TGT to handle potential expiration UserGroupInformation.getCurrentUser().checkTGTAndReloginFromKeytab(); + LOG.debug("No delegation token found for url={}, token={}, authenticating" + + " with {}", url, token, authenticator.getClass()); authenticator.authenticate(url, token); + } else { + LOG.debug("Authenticated from delegation token. url={}, token={}", + url, token); } }