From ffaf24e308506ec4c27104bf6b3769328e55c1c6 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. (cherry picked from commit 4a56bde6ba1f72588a25cd96acc76089706cb786) Conflicts: hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/token/delegation/web/DelegationTokenAuthenticationHandler.java --- .../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 6604c3ffc15..5696ba0bd85 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 264d9916c00..22b5a86eb6d 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 88702d94fb5..87223d157da 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 e9b66774eba..0fb16224c64 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 @@ -586,6 +586,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) { @@ -600,6 +604,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 @@ -1011,11 +1019,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 4b14059821e..cf887450324 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 4dedf92f5bd..0b1fdf80c9f 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 c23a94f0784..05abe2770a3 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 @@ -49,6 +49,8 @@ import org.apache.hadoop.util.HttpExceptionUtils; import org.apache.hadoop.util.StringUtils; import org.codehaus.jackson.map.ObjectMapper; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import com.google.common.annotations.VisibleForTesting; @@ -77,6 +79,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"; @@ -190,6 +194,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; @@ -202,6 +207,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; @@ -350,6 +356,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); @@ -367,6 +374,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 2d60d4ada01..b7db5a69e20 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); } }