HADOOP-18958. Improve UserGroupInformation debug log. (#6255)

Contributed by zhihui wang

hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/security/UserGroupInformation.java

@@ -88,6 +88,7 @@
 import org.apache.hadoop.security.token.Token;
 import org.apache.hadoop.security.token.TokenIdentifier;
 import org.apache.hadoop.util.Shell;
+import org.apache.hadoop.util.StringUtils;
 import org.apache.hadoop.util.Time;
 
 import org.slf4j.Logger;
@@ -1934,10 +1935,7 @@ protected Subject getSubject() {
   @InterfaceAudience.Public
   @InterfaceStability.Evolving
   public <T> T doAs(PrivilegedAction<T> action) {
-    if (LOG.isDebugEnabled()) {
+    tracePrivilegedAction(action);
-      LOG.debug("PrivilegedAction [as: {}][action: {}]", this, action,
-          new Exception());
-    }
     return Subject.doAs(subject, action);
   }
   
@@ -1957,10 +1955,7 @@ public <T> T doAs(PrivilegedAction<T> action) {
   public <T> T doAs(PrivilegedExceptionAction<T> action
                     ) throws IOException, InterruptedException {
     try {
-      if (LOG.isDebugEnabled()) {
+      tracePrivilegedAction(action);
-        LOG.debug("PrivilegedAction [as: {}][action: {}]", this, action,
-            new Exception());
-      }
       return Subject.doAs(subject, action);
     } catch (PrivilegedActionException pae) {
       Throwable cause = pae.getCause();
@@ -1982,6 +1977,14 @@ public <T> T doAs(PrivilegedExceptionAction<T> action
     }
   }
 
+  private void tracePrivilegedAction(Object action) {
+    if (LOG.isTraceEnabled()) {
+      // would be nice if action included a descriptive toString()
+      LOG.trace("PrivilegedAction [as: {}][action: {}][from: {}]", this, action,
+          StringUtils.getStackTrace(new Throwable()));
+    }
+  }
+
   /**
    * Log current UGI and token information into specified log.
    * @param ugi - UGI

hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/StringUtils.java

@@ -1148,6 +1148,19 @@ public static String getStackTrace(Thread t) {
     return str.toString();
   }
 
+  /**
+   * Get stack trace from throwable exception.
+   * @param t Throwable.
+   * @return stack trace string.
+   */
+  public static String getStackTrace(Throwable t) {
+    StringBuilder str = new StringBuilder();
+    for (StackTraceElement e : t.getStackTrace()) {
+      str.append(e.toString() + "\n\t");
+    }
+    return str.toString();
+  }
+
   /**
    * From a list of command-line arguments, remove both an option and the 
    * next argument.

hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/TestStringUtils.java

@@ -624,6 +624,15 @@ public void testStringCollectionSplitByEqualsFailure() throws Exception {
         () -> StringUtils.getTrimmedStringCollectionSplitByEquals(",="));
   }
 
+  @Test
+  public void testForGetStackTrace() {
+    Throwable throwable = new Throwable();
+    int stackLength = throwable.getStackTrace().length;
+    String stackTrace = StringUtils.getStackTrace(new Throwable());
+    String[] splitTrace = stackTrace.split("\n\t");
+    assertEquals(stackLength, splitTrace.length);
+  }
+
   // Benchmark for StringUtils split
   public static void main(String []args) {
     final String TO_SPLIT = "foo,bar,baz,blah,blah";