HADOOP-13174. Add more debug logs for delegation tokens and authentication.

This commit is contained in:
Xiao Chen 2017-06-08 21:27:06 -07:00
parent 7c9694c567
commit 0202480742
8 changed files with 60 additions and 2 deletions

View File

@ -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 @@
* </pre>
*/
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() +

View File

@ -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) {

View File

@ -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);

View File

@ -590,6 +590,10 @@ private <T> 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> 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 {

View File

@ -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);
}
}

View File

@ -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 <code>DO_AS</code> parameter is the user the request will be
@ -283,17 +288,23 @@ public HttpURLConnection openConnection(URL url, Token token, String doAs)
Map<String, String> extraParams = new HashMap<String, String>();
org.apache.hadoop.security.token.Token<? extends TokenIdentifier> 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

View File

@ -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<AbstractDelegationTokenIdentifier> 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;

View File

@ -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);
}
}