Skip to content

HADOOP-16691: Unify Logging in UserGroupInformation #1716

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Nov 14, 2019
Merged

HADOOP-16691: Unify Logging in UserGroupInformation #1716

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
84dbae0
HADOOP-16691: Unify Logging in UserGroupInformation
belugabehr Nov 13, 2019
d143723
Added changes from review
belugabehr Nov 13, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
108 changes: 35 additions & 73 deletions ...-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -189,21 +189,15 @@ private <T extends Principal> T getCanonicalUser(Class<T> cls) {

@Override
public boolean commit() throws LoginException {
if (LOG.isDebugEnabled()) {
LOG.debug("hadoop login commit");
}
LOG.debug("hadoop login commit");
// if we already have a user, we are done.
if (!subject.getPrincipals(User.class).isEmpty()) {
if (LOG.isDebugEnabled()) {
LOG.debug("using existing subject:"+subject.getPrincipals());
}
LOG.debug("Using existing subject: {}", subject.getPrincipals());
return true;
}
Principal user = getCanonicalUser(KerberosPrincipal.class);
if (user != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("using kerberos user:"+user);
}
LOG.debug("Using kerberos user: {}", user);
}
//If we don't have a kerberos user and security is disabled, check
//if user is specified in the environment or properties
Expand All @@ -217,15 +211,11 @@ public boolean commit() throws LoginException {
// use the OS user
if (user == null) {
user = getCanonicalUser(OS_PRINCIPAL_CLASS);
if (LOG.isDebugEnabled()) {
LOG.debug("using local user:"+user);
}
LOG.debug("Using local user: {}", user);
}
// if we found the user, add our principal
if (user != null) {
if (LOG.isDebugEnabled()) {
LOG.debug("Using user: \"" + user + "\" with name " + user.getName());
}
LOG.debug("Using user: \"{}\" with name: {}", user, user.getName());

User userEntry = null;
try {
Expand All @@ -237,15 +227,12 @@ public boolean commit() throws LoginException {
} catch (Exception e) {
throw (LoginException)(new LoginException(e.toString()).initCause(e));
}
if (LOG.isDebugEnabled()) {
LOG.debug("User entry: \"" + userEntry.toString() + "\"" );
}
LOG.debug("User entry: \"{}\"", userEntry);

subject.getPrincipals().add(userEntry);
return true;
}
LOG.error("Can't find user in " + subject);
throw new LoginException("Can't find user name");
throw new LoginException("Failed to find user in name " + subject);
}

@Override
Expand All @@ -256,17 +243,13 @@ public void initialize(Subject subject, CallbackHandler callbackHandler,

@Override
public boolean login() throws LoginException {
if (LOG.isDebugEnabled()) {
LOG.debug("hadoop login");
}
LOG.debug("Hadoop login");
return true;
}

@Override
public boolean logout() throws LoginException {
if (LOG.isDebugEnabled()) {
LOG.debug("hadoop logout");
}
LOG.debug("Hadoop logout");
return true;
}
}
Expand Down Expand Up @@ -808,12 +791,10 @@ UserGroupInformation createLoginUser(Subject subject) throws IOException {
LOG.debug("Loaded {} base64 tokens", numTokenBase64);
}
} catch (IOException ioe) {
LOG.debug("failure to load login credentials", ioe);
LOG.debug("Failure to load login credentials", ioe);
throw ioe;
}
if (LOG.isDebugEnabled()) {
LOG.debug("UGI loginUser:"+loginUser);
}
LOG.debug("UGI loginUser: {}", loginUser);
return loginUser;
}

Expand Down Expand Up @@ -994,10 +975,7 @@ public void run() {
do {
try {
long now = Time.now();
if (LOG.isDebugEnabled()) {
LOG.debug("Current time is " + now);
LOG.debug("Next refresh is " + nextRefresh);
}
LOG.debug("Current time is {}, next refresh is {}", now, nextRefresh);
if (now < nextRefresh) {
Thread.sleep(nextRefresh - now);
}
Expand Down Expand Up @@ -1033,18 +1011,18 @@ public void run() {
try {
tgtEndTime = tgt.getEndTime().getTime();
} catch (NullPointerException npe) {
LOG.error(String.format("NPE thrown while getting " +
"KerberosTicket endTime. Aborting renew thread for %s.",
getUserName()), ie);
LOG.error("NPE thrown while getting KerberosTicket endTime. "
+ "Aborting renew thread for {}.", getUserName(), ie);
return;
}

LOG.warn(String.format("Exception encountered while running the " +
"renewal command for %s. " +
"(TGT end time:%d, renewalFailures: %d, " +
"renewalFailuresTotal: %d)", getUserName(), tgtEndTime,
metrics.renewalFailures.value(),
metrics.renewalFailuresTotal.value()), ie);
LOG.warn(
"Exception encountered while running the "
+ "renewal command for {}. "
+ "(TGT end time:{}, renewalFailures: {}, "
+ "renewalFailuresTotal: {})",
getUserName(), tgtEndTime, metrics.renewalFailures.value(),
metrics.renewalFailuresTotal.value(), ie);
if (rp == null) {
// Use a dummy maxRetries to create the policy. The policy will
// only be used to get next retry time with exponential back-off.
Expand Down Expand Up @@ -1091,9 +1069,7 @@ final class TicketCacheRenewalRunnable
@Override
public void relogin() throws IOException {
String output = Shell.execCommand(kinitCmd, "-R");
if (LOG.isDebugEnabled()) {
LOG.debug("Renewed ticket. kinit output: {}", output);
}
LOG.debug("Renewed ticket. kinit output: {}", output);
reloginFromTicketCache();
}
}
Expand Down Expand Up @@ -1193,9 +1169,7 @@ public void logoutUserFromKeytab() throws IOException {
}

try {
if (LOG.isDebugEnabled()) {
LOG.debug("Initiating logout for " + getUserName());
}
LOG.debug("Initiating logout for {}", getUserName());
// hadoop login context internally locks credentials.
login.logout();
} catch (LoginException le) {
Expand Down Expand Up @@ -1329,9 +1303,7 @@ private void unprotectedRelogin(HadoopLoginContext login) throws IOException {
// register most recent relogin attempt
user.setLastLogin(now);
try {
if (LOG.isDebugEnabled()) {
LOG.debug("Initiating logout for " + getUserName());
}
LOG.debug("Initiating logout for {}", getUserName());
//clear up the kerberos state. But the tokens are not cleared! As per
//the Java kerberos login module code, only the kerberos credentials
//are cleared
Expand All @@ -1340,9 +1312,7 @@ private void unprotectedRelogin(HadoopLoginContext login) throws IOException {
//have the new credentials (pass it to the LoginContext constructor)
login = newLoginContext(
login.getAppName(), login.getSubject(), login.getConfiguration());
if (LOG.isDebugEnabled()) {
LOG.debug("Initiating re-login for " + getUserName());
}
LOG.debug("Initiating re-login for {}", getUserName());
login.login();
// this should be unnecessary. originally added due to improper locking
// of the subject during relogin.
Expand Down Expand Up @@ -1748,11 +1718,7 @@ public List<String> getGroups() {
try {
return groups.getGroups(getShortUserName());
} catch (IOException ie) {
if (LOG.isDebugEnabled()) {
LOG.debug("Failed to get groups for user " + getShortUserName()
+ " by " + ie);
LOG.trace("TRACE", ie);
}
LOG.debug("Failed to get groups for user {}", getShortUserName(), ie);
return Collections.emptyList();
}
}
Expand Down Expand Up @@ -1867,7 +1833,10 @@ protected Subject getSubject() {
@InterfaceAudience.Public
@InterfaceStability.Evolving
public <T> T doAs(PrivilegedAction<T> action) {
logPrivilegedAction(subject, action);
if (LOG.isDebugEnabled()) {
LOG.debug("PrivilegedAction [as: {}][action: {}]", this, action,
new Exception());
}
return Subject.doAs(subject, action);
}

Expand All @@ -1887,13 +1856,14 @@ public <T> T doAs(PrivilegedAction<T> action) {
public <T> T doAs(PrivilegedExceptionAction<T> action
) throws IOException, InterruptedException {
try {
logPrivilegedAction(subject, action);
if (LOG.isDebugEnabled()) {
LOG.debug("PrivilegedAction [as: {}][action: {}]", this, action,
new Exception());
}
return Subject.doAs(subject, action);
} catch (PrivilegedActionException pae) {
Throwable cause = pae.getCause();
if (LOG.isDebugEnabled()) {
LOG.debug("PrivilegedActionException as:" + this + " cause:" + cause);
}
LOG.debug("PrivilegedActionException as: {}", this, cause);
if (cause == null) {
throw new RuntimeException("PrivilegedActionException with no " +
"underlying cause. UGI [" + this + "]" +": " + pae, pae);
Expand All @@ -1911,14 +1881,6 @@ public <T> T doAs(PrivilegedExceptionAction<T> action
}
}

private void logPrivilegedAction(Subject subject, Object action) {
if (LOG.isDebugEnabled()) {
// would be nice if action included a descriptive toString()
String where = new Throwable().getStackTrace()[2].toString();
LOG.debug("PrivilegedAction as:"+this+" from:"+where);
}
}

/**
* Log current UGI and token information into specified log.
* @param ugi - UGI
Expand Down