From d0302d3849cc4f801f3b7d417b2c7bd7378d51e9 Mon Sep 17 00:00:00 2001 From: belugabehr <12578579+belugabehr@users.noreply.github.com> Date: Thu, 14 Nov 2019 13:28:26 -0500 Subject: [PATCH] HADOOP-16691. Unify Logging in UserGroupInformation. Unify Logging in UserGroupInformation. --- .../hadoop/security/UserGroupInformation.java | 108 ++++++------------ 1 file changed, 35 insertions(+), 73 deletions(-) diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java index 91c51f2a32..73a09a7e83 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java @@ -189,21 +189,15 @@ public class UserGroupInformation { @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 @@ -217,15 +211,11 @@ public class UserGroupInformation { // 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 { @@ -237,15 +227,12 @@ public class UserGroupInformation { } 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 @@ -256,17 +243,13 @@ public class UserGroupInformation { @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; } } @@ -808,12 +791,10 @@ public class UserGroupInformation { 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; } @@ -994,10 +975,7 @@ public class UserGroupInformation { 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); } @@ -1033,18 +1011,18 @@ public class UserGroupInformation { 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. @@ -1091,9 +1069,7 @@ public class UserGroupInformation { @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(); } } @@ -1193,9 +1169,7 @@ public class UserGroupInformation { } 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) { @@ -1329,9 +1303,7 @@ public class UserGroupInformation { // 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 @@ -1340,9 +1312,7 @@ public class UserGroupInformation { //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. @@ -1748,11 +1718,7 @@ public class UserGroupInformation { 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(); } } @@ -1867,7 +1833,10 @@ public class UserGroupInformation { @InterfaceAudience.Public @InterfaceStability.Evolving public T doAs(PrivilegedAction action) { - logPrivilegedAction(subject, action); + if (LOG.isDebugEnabled()) { + LOG.debug("PrivilegedAction [as: {}][action: {}]", this, action, + new Exception()); + } return Subject.doAs(subject, action); } @@ -1887,13 +1856,14 @@ public class UserGroupInformation { public T doAs(PrivilegedExceptionAction 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); @@ -1911,14 +1881,6 @@ public class UserGroupInformation { } } - 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