[ZEPPELIN-5180] - Improve Kerberos debug messages

### What is this PR for? While troubleshooting Kerberos ticket issue, lack of Kerberos log messages makes it difficult to understand what is really happening. This PR aims to address that. It adds debug level log4j messages around ticket renewal thread (in runKerberosLogin()) and in createSecureConfiguration(). ### What type of PR is it? [Improvement] ### Todos * none ### What is the Jira issue? * https://issues.apache.org/jira/browse/ZEPPELIN-5180 ### How should this be tested? * Enable debug level in log4j for Interpreter to see the debug messages ### Screenshots (if appropriate) * None ### Questions: * Does the licenses files need update? No * Is there breaking changes for older versions? No * Does this needs documentation? No Author: Vipin Rathor <v.rathor@gmail.com> Closes apache#4007 from VipinRathor/ZEPPELIN-5180 and squashes the following commits: 2534ba2 [Vipin Rathor] ZEPPELIN-5180 Incorporating more review comments 2cbc877 [Vipin Rathor] ZEPPELIN-5180 Incorporating review comments. f63ad05 [Vipin Rathor] ZEPPELIN-5180 - Improve Kerberos debug messages
Elvis0607 · Jan 5, 2021 · 76ff234 · 76ff234
1 parent 71d2508
commit 76ff234
Show file tree

Hide file tree

Showing 2 changed files with 16 additions and 7 deletions.
diff --git a/jdbc/src/main/java/org/apache/zeppelin/jdbc/JDBCInterpreter.java b/jdbc/src/main/java/org/apache/zeppelin/jdbc/JDBCInterpreter.java
@@ -188,15 +188,19 @@ protected boolean runKerberosLogin() {
     UserGroupInformation.setConfiguration(conf);
     try {
       if (UserGroupInformation.isLoginKeytabBased()) {
+        LOGGER.debug("Trying relogin from keytab");
         UserGroupInformation.getLoginUser().reloginFromKeytab();
         return true;
       } else if (UserGroupInformation.isLoginTicketBased()) {
+        LOGGER.debug("Trying relogin from ticket cache");
         UserGroupInformation.getLoginUser().reloginFromTicketCache();
         return true;
       }
     } catch (Exception e) {
       LOGGER.error("Unable to run kinit for zeppelin", e);
     }
+    LOGGER.debug("Neither Keytab nor ticket based login. " +
+      "runKerberosLogin() returning false");
     return false;
   }
 
@@ -516,8 +520,11 @@ public Connection getConnection(String dbPrefix, InterpreterContext context)
         connection = getConnectionFromPool(connectionUrl, user, dbPrefix, properties);
         break;
       case "KERBEROS":
+        LOGGER.debug("Calling createSecureConfiguration(); this will do " +
+          "loginUserFromKeytab() if required");
         JDBCSecurityImpl.createSecureConfiguration(getProperties(),
                 UserGroupInformation.AuthenticationMethod.KERBEROS);
+        LOGGER.debug("createSecureConfiguration() returned");
         boolean isProxyEnabled = Boolean.parseBoolean(
                 getProperty("zeppelin.jdbc.auth.kerberos.proxy.enable", "true"));
         if (basePropertiesMap.get(dbPrefix).containsKey("proxy.user.property")

diff --git a/zeppelin-interpreter/src/main/java/org/apache/zeppelin/interpreter/KerberosInterpreter.java b/zeppelin-interpreter/src/main/java/org/apache/zeppelin/interpreter/KerberosInterpreter.java
@@ -48,7 +48,7 @@ public abstract class KerberosInterpreter extends AbstractInterpreter {
 
   private Integer kinitFailCount = 0;
   private ScheduledExecutorService scheduledExecutorService;
-  private static Logger logger = LoggerFactory.getLogger(KerberosInterpreter.class);
+  private static final Logger LOGGER = LoggerFactory.getLogger(KerberosInterpreter.class);
 
   public KerberosInterpreter(Properties property) {
     super(property);
@@ -82,7 +82,7 @@ private Long getKerberosRefreshInterval() {
     try {
       refreshInterval = getTimeAsMs(refreshIntervalString);
     } catch (IllegalArgumentException e) {
-      logger.error("Cannot get time in MS for the given string, " + refreshIntervalString
+      LOGGER.error("Cannot get time in MS for the given string, " + refreshIntervalString
           + " defaulting to 1d ", e);
       refreshInterval = getTimeAsMs("1d");
     }
@@ -97,7 +97,7 @@ private Integer kinitFailThreshold() {
       try {
         kinitFailThreshold = new Integer(System.getenv("KINIT_FAIL_THRESHOLD"));
       } catch (Exception e) {
-        logger.error("Cannot get integer value from the given string, " + System
+        LOGGER.error("Cannot get integer value from the given string, " + System
             .getenv("KINIT_FAIL_THRESHOLD") + " defaulting to " + kinitFailThreshold, e);
       }
     }
@@ -106,7 +106,7 @@ private Integer kinitFailThreshold() {
 
   private Long getTimeAsMs(String time) {
     if (time == null) {
-      logger.error("Cannot convert to time value.", time);
+      LOGGER.error("Cannot convert null to a time value. Defaulting to 1d");
       time = "1d";
     }
 
@@ -133,17 +133,19 @@ private ScheduledExecutorService startKerberosLoginThread() {
       public Object call() throws Exception {
 
         if (runKerberosLogin()) {
-          logger.info("Ran runKerberosLogin command successfully.");
+          LOGGER.info("Ran runKerberosLogin command successfully.");
           kinitFailCount = 0;
           // schedule another kinit run with a fixed delay.
+          LOGGER.info("Scheduling Kerberos ticket refresh thread with interval {} ms",
+            getKerberosRefreshInterval());
           scheduledExecutorService
               .schedule(this, getKerberosRefreshInterval(), TimeUnit.MILLISECONDS);
         } else {
           kinitFailCount++;
-          logger.info("runKerberosLogin failed for " + kinitFailCount + " time(s).");
+          LOGGER.info("runKerberosLogin failed for {} time(s).", kinitFailCount);
           // schedule another retry at once or close the interpreter if too many times kinit fails
           if (kinitFailCount >= kinitFailThreshold()) {
-            logger.error("runKerberosLogin failed for  max attempts, calling close interpreter.");
+            LOGGER.error("runKerberosLogin failed for  max attempts, calling close interpreter.");
             close();
           } else {
             // wait for 1 second before calling runKerberosLogin() again