SENTRY-2205: Improve Sentry NN Logging. (Kalyan Kumar Kalvagadda reviewed by Arjun Mishra)

Change-Id: I20982f62f01bf4190ceee4f108191444fec50177
diff --git a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/HMSPaths.java b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/HMSPaths.java
index 97a04d9..a00a90a 100644
--- a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/HMSPaths.java
+++ b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/HMSPaths.java
@@ -199,10 +199,12 @@
         // memory waste due to empty and underpopulated maps.
         children = new HashMap<>(2);
       }
+      LOG.debug("[putChild]Adding {} as child to {}", entry.toString(), this.toString());
       children.put(pathElement.intern(), entry);
     }
 
     Entry removeChild(String pathElement) {
+      LOG.debug("[removeChild]Removing {} from children {}", pathElement, childrenValues());
       return children.remove(pathElement);
     }
 
@@ -215,10 +217,12 @@
     }
 
     void clearAuthzObjs() {
+      LOG.debug("Clearing authzObjs from {}", this.toString());
       authzObjs = null;
     }
 
     void removeAuthzObj(String authzObj) {
+      LOG.debug("Removing {} from {}", authzObj, authzObjs);
       if (authzObjs != null) {
         if (authzObjs instanceof Set) {
           Set<String> authzObjsSet = (Set<String>) authzObjs;
@@ -233,6 +237,7 @@
     }
 
     void addAuthzObj(String authzObj) {
+      LOG.debug("Adding {} to {}", authzObj, this.toString());
       if (authzObj != null) {
         if (authzObjs == null) {
           authzObjs = authzObj;
@@ -250,9 +255,11 @@
           authzObjsSet.add(authzObj.intern());
         }
       }
+      LOG.debug("Added {} to {}", authzObj, this.toString());
     }
 
     void addAuthzObjs(Collection<String> authzObjs) {
+      LOG.debug("Adding {} to {}", authzObjs, this.toString());
       if (authzObjs != null) {
         for (String authzObj : authzObjs) {
           addAuthzObj(authzObj.intern());
@@ -356,6 +363,7 @@
      */
     private Entry createParent(List<String> pathElements) {
       Entry parent = this;
+      LOG.debug("[createParent]Trying to create entires for {} ", pathElements);
       // The loop is resilient to 0 or 1 element list.
       for (int i = 0; i < pathElements.size() - 1; i++) {
         String elem = pathElements.get(i);
@@ -364,6 +372,7 @@
         if (child == null) {
           child = new Entry(parent, elem, EntryType.DIR, (String) null);
           parent.putChild(elem, child);
+          LOG.debug("[createParent] Entry {} created", child.toString());
         }
 
         parent = child;
@@ -382,7 +391,7 @@
      */
     private Entry createChild(List<String> pathElements, EntryType type,
         String authzObj) {
-
+      LOG.debug("[createChild] Creating child for {} with path {}", authzObj, pathElements);
       // Create all the parent entries on the path if they do not exist.
       Entry entryParent = createParent(pathElements);
 
@@ -396,19 +405,24 @@
       if (child == null) {
         child = new Entry(entryParent, lastPathElement, type, authzObj);
         entryParent.putChild(lastPathElement, child);
+        LOG.debug("Created child entry {}", child);
       } else if (type == EntryType.AUTHZ_OBJECT &&
           (child.getType() == EntryType.PREFIX || child.getType() == EntryType.AUTHZ_OBJECT)) {
         child.addAuthzObj(authzObj);
+        LOG.debug("[createChild] Found Child {}, updated authzObj", child.toString());
       } else if (type == EntryType.AUTHZ_OBJECT &&
           child.getType() == EntryType.DIR) {
         child.addAuthzObj(authzObj);
         child.setType(EntryType.AUTHZ_OBJECT);
+        LOG.debug("[createChild] Found Child {}, updated authzObj", child.toString());
+        LOG.debug("[createChild] Updating type to", child.getType().toString());
       }
 
       return child;
     }
 
     public static Entry createRoot(boolean asPrefix) {
+      LOG.debug("Creating entry for root");
       return new Entry(null, "/", asPrefix
                                    ? EntryType.PREFIX : EntryType.DIR, (String) null);
     }
@@ -422,6 +436,7 @@
     }
 
     public Entry createPrefix(List<String> pathElements) {
+      LOG.debug("Creating entries for prefix paths", pathElements.toString());
       Entry prefix = findPrefixEntry(pathElements);
       if (prefix != null) {
         throw new IllegalArgumentException(String.format(
@@ -433,6 +448,7 @@
 
     public Entry createAuthzObjPath(List<String> pathElements, String authzObj) {
       Entry entry = null;
+      LOG.debug("createAuthzObjPath authzObj:{} paths: {}", authzObj, pathElements);
       Entry prefix = findPrefixEntry(pathElements);
       if (prefix != null) {
         // we only create the entry if is under a prefix, else we ignore it
@@ -450,14 +466,19 @@
      * Delete this entry from its parent.
      */
     private void deleteFromParent() {
+      LOG.debug("[deleteFromParent] Attempting to remove path: {}", this.getFullPath());
       if (getParent() != null) {
+        LOG.debug("Child in Parent Entry with path: {} is removed", getParent().getFullPath());
         getParent().removeChild(getPathElement());
         getParent().deleteIfDangling();
         parent = null;
+      } else {
+        LOG.warn("Parent for {} not found", this.toString());
       }
     }
 
     public void deleteAuthzObject(String authzObj) {
+      LOG.debug("[deleteAuthzObject] Removing authObj:{} from path {}", authzObj, this.toString());
       if (getParent() != null) {
         if (!hasChildren()) {
 
@@ -468,6 +489,7 @@
             removeAuthzObj(authzObj);
           }
           if (authzObjs == null) {
+            LOG.debug("Deleting path {}", this.toString());
             deleteFromParent();
           }
         } else {
@@ -476,6 +498,7 @@
           // change it to be a dir entry. And remove the authzObj on
           // the path entry.
           if (getType() == EntryType.AUTHZ_OBJECT) {
+            LOG.debug("Entry with path: {} is changed to DIR", this.getFullPath());
             setType(EntryType.DIR);
             if (authzObjs != null) {
               removeAuthzObj(authzObj);
@@ -493,6 +516,7 @@
      * @return true if success. Returns false if the target with the same name already exists.
      */
     private void moveTo(Entry newParent, String pathElem) {
+      LOG.debug("Moving {} as a child to {}", this.toString(), newParent.toString());
       Preconditions.checkNotNull(newParent);
       Preconditions.checkArgument(!pathElem.isEmpty());
       if (newParent.getChild(pathElem) != null) {
@@ -517,6 +541,8 @@
           if (getType() == EntryType.AUTHZ_OBJECT) {
             setType(EntryType.DIR);
             clearAuthzObjs();
+            LOG.debug("Entry with path: {} is changed to DIR", this.getFullPath());
+
           }
         }
       }
@@ -524,6 +550,7 @@
 
     private void deleteIfDangling() {
       if (!hasChildren() && getType().isRemoveIfDangling()) {
+        LOG.debug("Deleting {} as it is dangling", this.toString());
         delete();
       }
     }
@@ -684,7 +711,7 @@
     }
 
     authzObjToEntries = new TreeMap<String, Set<Entry>>(String.CASE_INSENSITIVE_ORDER);
-    LOG.info(toString() + " Initialized");
+    LOG.info("Sentry managed prefixes: " + prefixes.toString());
   }
 
   void _addAuthzObject(String authzObj, List<String> authzObjPaths) {
@@ -692,10 +719,9 @@
   }
 
   void addAuthzObject(String authzObj, List<List<String>> authzObjPathElements) {
-    if (LOG.isDebugEnabled()) {
-      LOG.debug(String.format("%s addAuthzObject(%s, %s)",
-        this, authzObj, assemblePaths(authzObjPathElements)));
-    }
+    LOG.debug("Number of Objects: {}", authzObjToEntries.size());
+    LOG.debug(String.format("%s addAuthzObject(%s, %s)",
+              this, authzObj, assemblePaths(authzObjPathElements)));
     Set<Entry> previousEntries = authzObjToEntries.get(authzObj);
     Set<Entry> newEntries = new HashSet<Entry>(authzObjPathElements.size());
     for (List<String> pathElements : authzObjPathElements) {
@@ -709,10 +735,12 @@
       }
     }
     authzObjToEntries.put(authzObj, newEntries);
+    LOG.debug("Path entries for {} are {}", authzObj, newEntries.toString());
     if (previousEntries != null) {
       previousEntries.removeAll(newEntries);
       if (!previousEntries.isEmpty()) {
         for (Entry entry : previousEntries) {
+          LOG.debug("Removing stale path {}", entry.toString());
           entry.deleteAuthzObject(authzObj);
         }
       }
@@ -723,7 +751,7 @@
       List<List<String>> authzObjPathElements, boolean createNew) {
     if (LOG.isDebugEnabled()) {
       LOG.debug(String.format("%s addPathsToAuthzObject(%s, %s, %b)",
-        this, authzObj, assemblePaths(authzObjPathElements), createNew));
+              this, authzObj, assemblePaths(authzObjPathElements), createNew));
     }
     Set<Entry> entries = authzObjToEntries.get(authzObj);
     if (entries != null) {
@@ -741,8 +769,10 @@
         }
       }
       entries.addAll(newEntries);
+      LOG.debug("[addPathsToAuthzObject]Updated path entries for {} are {}", authzObj, entries.toString());
     } else {
       if (createNew) {
+        LOG.debug("No paths found for Object:{}, Adding new", authzObj);
         addAuthzObject(authzObj, authzObjPathElements);
       } else {
         LOG.warn(String.format("%s addPathsToAuthzObject(%s, %s, %b):" +
@@ -767,11 +797,8 @@
    */
   void deletePathsFromAuthzObject(String authzObj,
       List<List<String>> authzObjPathElements) {
-    if (LOG.isDebugEnabled()) {
-      LOG.debug(String.format("%s deletePathsFromAuthzObject(%s, %s)",
-        this, authzObj, assemblePaths(authzObjPathElements)));
-    }
     Set<Entry> entries = authzObjToEntries.get(authzObj);
+    LOG.debug("[deletePathsFromAuthzObject] Paths for {} before delete are {}", authzObj, entries.toString());
     if (entries != null) {
       Set<Entry> toDelEntries = new HashSet<Entry>(authzObjPathElements.size());
       for (List<String> pathElements : authzObjPathElements) {
@@ -788,6 +815,7 @@
         }
       }
       entries.removeAll(toDelEntries);
+      LOG.debug("[deletePathsFromAuthzObject] Paths for {} after are {}", authzObj, entries.toString());
     } else {
       LOG.warn(String.format("%s deletePathsFromAuthzObject(%s, %s):" +
         " Path was not deleted from AuthzObject, could not find key in authzObjToPath",
@@ -795,10 +823,9 @@
     }
   }
 
-  void deleteAuthzObject(String authzObj) {
-    if (LOG.isDebugEnabled()) {
+    void deleteAuthzObject(String authzObj) {
       LOG.debug(String.format("%s deleteAuthzObject(%s)", this, authzObj));
-    }
+      LOG.debug("Number of Objects: {}", authzObjToEntries.size());
     Set<Entry> entries = authzObjToEntries.remove(authzObj);
     if (entries != null) {
       for (Entry entry : entries) {
diff --git a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/SentryAuthzUpdate.java b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/SentryAuthzUpdate.java
index db11c1e..a8a195e 100644
--- a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/SentryAuthzUpdate.java
+++ b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/SentryAuthzUpdate.java
@@ -41,10 +41,10 @@
   public String dumpContent() {
     StringBuffer sb = new StringBuffer(getClass().getSimpleName());
     if (permUpdates != null && !permUpdates.isEmpty()) {
-      sb.append(", perms[").append(permUpdates.size()).append(']').append(permUpdates);
+      sb.append(", Permission Updates[").append(permUpdates.size()).append(']').append(permUpdates);
     }
     if (pathUpdates != null && !pathUpdates.isEmpty()) {
-      sb.append(", paths[").append(pathUpdates.size()).append(']').append(pathUpdates);
+      sb.append(", Path Updates[").append(pathUpdates.size()).append(']').append(pathUpdates);
     }
     return sb.toString();
   }
diff --git a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/Updateable.java b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/Updateable.java
index bbf3f13..66b5208 100644
--- a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/Updateable.java
+++ b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/Updateable.java
@@ -98,4 +98,8 @@
 
   String getUpdateableTypeName();
 
+  /**
+  Get the string with the sequence and image number.
+  */
+  String getSequenceInfo();
 }
diff --git a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPaths.java b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPaths.java
index c967f4e..bf84f4d 100644
--- a/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPaths.java
+++ b/sentry-hdfs/sentry-hdfs-common/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPaths.java
@@ -114,6 +114,7 @@
       }
       if (newPathInfo != null && oldPathInfo != null &&
               !newPathInfo.getAuthzObj().equalsIgnoreCase(oldPathInfo.getAuthzObj())) {
+        LOG.info("Renaming Object:{} to {}",  oldPathInfo.getAuthzObj(), newPathInfo.getAuthzObj());
         paths.renameAuthzObject(
             oldPathInfo.getAuthzObj(), oldPathInfo.getDelPaths(),
             newPathInfo.getAuthzObj(), newPathInfo.getAddPaths());
@@ -137,13 +138,18 @@
       if (delPaths.size() == 1 && delPaths.get(0).size() == 1
               && delPaths.get(0).get(0).equals(PathsUpdate.ALL_PATHS)) {
         // Remove all paths.. eg. drop table
+        LOG.info("Applying Path update. Deleting all paths for authz obj {}", pathChanges.getAuthzObj());
         paths.deleteAuthzObject(pathChanges.getAuthzObj());
       } else {
+        LOG.info("Applying Path update. Deleting path for authz object: {} authz path: {}",
+            pathChanges.getAuthzObj(), pathChanges.getDelPaths());
         paths.deletePathsFromAuthzObject(pathChanges.getAuthzObj(), pathChanges
                 .getDelPaths());
       }
     }
     for (TPathChanges pathChanges : addPathChanges) {
+      LOG.info("Applying Path update. Adding path for authz object {} authz path {}",
+          pathChanges.getAuthzObj(), pathChanges.getAddPaths());
       applyAddChanges(pathChanges.getAuthzObj(), pathChanges.getAddPaths());
     }
   }
@@ -197,6 +203,11 @@
     return String.format("%s(%s, %s, %s)", getClass().getSimpleName(), seqNum, imgNum, paths);
   }
 
+  @Override
+  public String getSequenceInfo() {
+    return String.format("%s(Path: Sequence Number %s, Image Number: %s)", getClass().getSimpleName(), seqNum, imgNum);
+  }
+
   public String dumpContent() {
     return String.format("%s(%s, %s) ", getClass().getSimpleName(), seqNum, imgNum) + paths.dumpContent();
   }
diff --git a/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/SentryAuthorizationInfo.java b/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/SentryAuthorizationInfo.java
index 9dae035..9fe22ef 100644
--- a/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/SentryAuthorizationInfo.java
+++ b/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/SentryAuthorizationInfo.java
@@ -137,6 +137,9 @@
         return true; // no updates is a norm, it's still success
       }
 
+      LOG.info("Received updates from Sentry Server. Size of PathUpdates {} PermUpdates {}",
+          updates.getPathUpdates().size(), updates.getPermUpdates().size());
+      LOG.debug("Processing updates " + updates.dumpContent());
       UpdateableAuthzPaths newAuthzPaths = processUpdates(
           updates.getPathUpdates(), authzPaths);
       UpdateableAuthzPermissions newAuthzPerms = processUpdates(
@@ -148,9 +151,6 @@
       if (newAuthzPaths != authzPaths || newAuthzPerms != authzPermissions) {
         lock.writeLock().lock();
         try {
-          if (LOG.isDebugEnabled()) {
-            LOG.debug(updates.dumpContent());
-          }
           if (newAuthzPaths != authzPaths) {
             LOG.info(String.format("FULL Updated paths seq Num [old=%d], [new=%d]",
               authzPaths.getLastUpdatedSeqNum(), newAuthzPaths.getLastUpdatedSeqNum()));
@@ -185,6 +185,8 @@
         }
       }
       return true;
+    } else {
+      LOG.error("Received NULL updates from Sentry");
     }
     return false;
   }
@@ -196,27 +198,19 @@
     V newUpdateable = updateable;
     if (!updates.isEmpty()) {
       if (updates.get(0).hasFullImage()) {
-        String logMessage = String.format("Process Update : FULL IMAGE [%s][%d][%d]",
-            newUpdateable.getClass().getSimpleName(),
-            updates.get(0).getSeqNum(),
-            updates.get(0).getImgNum());
+        String logMessage = String.format("Processing Update : FULL IMAGE") + newUpdateable.getSequenceInfo();
         LOG.info(logMessage);
         System.out.println(SentryServiceUtil.getCurrentTimeStampWithMessage(logMessage));
         newUpdateable = (V)newUpdateable.updateFull(updates.remove(0));
+        LOG.info(String.format("Processing Update : Finished processing FULL IMAGE update.."));
       }
       // Any more elements ?
       if (!updates.isEmpty()) {
-        LOG.debug(String.format("Process Update : More updates.. [%s][%d][%d][%d]",
-            newUpdateable.getClass().getSimpleName(),
-            newUpdateable.getLastUpdatedSeqNum(),
-            newUpdateable.getLastUpdatedImgNum(),
-            updates.size()));
+        LOG.debug(String.format("Processing Update : Delta updates.. [%s] Count:[%d]",
+                newUpdateable.getSequenceInfo(), updates.size()));
         newUpdateable.updatePartial(updates, lock);
       }
-      LOG.debug(String.format("Process Update : Finished updates.. [%s][%d][%d]",
-          newUpdateable.getClass().getSimpleName(),
-          newUpdateable.getLastUpdatedSeqNum(),
-          newUpdateable.getLastUpdatedImgNum()));
+      LOG.debug(String.format("Processing Update : Finished updates.."));
     }
     return newUpdateable;
   }
@@ -237,6 +231,10 @@
       success = false;
       LOG.warn("Failed to update, will retry in [{}]ms, error: ", 
           new Object[]{ retryWaitMillisec, ex.getMessage(), ex});
+    } catch (Throwable t) {
+      LOG.error("Received a throwable while refreshing the cache" + t);
+      System.out.println("Received a throwable  while refreshing the cache " + t);
+      throw t;
     }
     if (success) {
       // we reset lastUpdate only on successful pulling
diff --git a/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPermissions.java b/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPermissions.java
index 5726c0e..354d697 100644
--- a/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPermissions.java
+++ b/sentry-hdfs/sentry-hdfs-namenode-plugin/src/main/java/org/apache/sentry/hdfs/UpdateableAuthzPermissions.java
@@ -94,6 +94,9 @@
 
   private void applyRoleUpdates(PermissionsUpdate update) {
     for (TRoleChanges rUpdate : update.getRoleUpdates()) {
+      LOG.debug("Applying privilege update on role:{} add group {}, role delete group {}", rUpdate.getRole(),
+              rUpdate.getAddGroups(), rUpdate.getDelGroups());
+
       if (rUpdate.getRole().equals(PermissionsUpdate.ALL_ROLES)) {
         // Request to remove group from all roles
         String groupToRemove = rUpdate.getDelGroups().iterator().next();
@@ -102,6 +105,7 @@
         }
       }
       RoleInfo rInfo = perms.getRoleInfo(rUpdate.getRole());
+      LOG.debug("RoleInfo Before: " + ((rInfo != null)  ? rInfo.toString() : "null"));
       for (String group : rUpdate.getAddGroups()) {
         if (rInfo == null) {
           rInfo = new RoleInfo(rUpdate.getRole());
@@ -120,12 +124,16 @@
           rInfo.delGroup(group);
         }
       }
+      LOG.debug("RoleInfo After: " + ((rInfo != null)  ? rInfo.toString() : "null"));
     }
   }
 
   private void applyPrivilegeUpdates(PermissionsUpdate update) {
     TPrivilegePrincipal addPrivEntity, delPrivEntity;
     for (TPrivilegeChanges pUpdate : update.getPrivilegeUpdates()) {
+      LOG.debug("Applying privilege update on object:{} add privileges {}, delete privileges {}", pUpdate.getAuthzObj(),
+      pUpdate.getAddPrivileges(), pUpdate.getDelPrivileges());
+
       if (pUpdate.getAuthzObj().equals(PermissionsUpdate.RENAME_PRIVS)) {
         addPrivEntity = pUpdate.getAddPrivileges().keySet().iterator().next();
         delPrivEntity = pUpdate.getDelPrivileges().keySet().iterator().next();
@@ -138,12 +146,14 @@
         }
         String newAuthzObj = addPrivEntity.getValue();
         String oldAuthzObj = delPrivEntity.getValue();
+        LOG.debug("Performing Rename from {} to {}", oldAuthzObj, newAuthzObj);
         PrivilegeInfo privilegeInfo = perms.getPrivilegeInfo(oldAuthzObj);
         // The privilegeInfo object can be null if no explicit Privileges
         // have been granted on the object. For eg. If grants have been applied on
         // Db, but no explicit grants on Table.. then the authzObject associated
         // with the table will never exist.
         if (privilegeInfo != null) {
+          LOG.debug("Permission info before rename " + privilegeInfo.toString());
           Map<TPrivilegePrincipal, FsAction> allPermissions = privilegeInfo.getAllPermissions();
           perms.delPrivilegeInfo(oldAuthzObj);
           perms.removeParentChildMappings(oldAuthzObj);
@@ -153,6 +163,7 @@
           }
           perms.addPrivilegeInfo(newPrivilegeInfo);
           perms.addParentChildMappings(newAuthzObj);
+          LOG.debug("Permission info before rename " + newPrivilegeInfo.toString());
         }
         return;
       }
@@ -160,9 +171,11 @@
         // Request to remove role from all Privileges
         delPrivEntity = pUpdate.getDelPrivileges().keySet().iterator().next();
         for (PrivilegeInfo pInfo : perms.getAllPrivileges()) {
+          LOG.debug("Role {} is revoked permission on {}", delPrivEntity.getValue(), pInfo.getAuthzObj());
           pInfo.removePermission(delPrivEntity);
         }
       }
+      logPermissionInfo("BEFORE-UPDATE",  pUpdate.getAuthzObj());
       PrivilegeInfo pInfo = perms.getPrivilegeInfo(pUpdate.getAuthzObj());
       for (Map.Entry<TPrivilegePrincipal, String> aMap : pUpdate.getAddPrivileges().entrySet()) {
         if (pInfo == null) {
@@ -208,6 +221,23 @@
           }
         }
       }
+      logPermissionInfo("AFTER-UPDATE",  pUpdate.getAuthzObj());
+    }
+  }
+
+  private void logPermissionInfo(String message, String objName) {
+    PrivilegeInfo pInfo = perms.getPrivilegeInfo(objName);
+    if(pInfo != null) {
+      LOG.debug("{} Permission info for {} is {}", message, objName, pInfo.toString());
+      Set<String> children = perms.getChildren(pInfo.getAuthzObj());
+      if (children != null) {
+        for (String child : children) {
+          PrivilegeInfo childInfo = perms.getPrivilegeInfo(child);
+          if(childInfo != null && !objName.equals(child)) {
+            LOG.debug("{} Permission info for {} is {}", message, childInfo.getAuthzObj(), childInfo.toString());
+          }
+        }
+      }
     }
   }
 
@@ -267,6 +297,11 @@
     return String.format("%s(%s, %s)", getClass().getSimpleName(), seqNum, perms);
   }
 
+  @Override
+  public String getSequenceInfo() {
+    return String.format("%s (Perm: Sequence Number %s)", getClass().getSimpleName(), seqNum);
+  }
+
   public String dumpContent() {
     return String.format("%s(%s) ", getClass().getSimpleName(), seqNum) + perms.dumpContent();
   }
diff --git a/sentry-hdfs/sentry-hdfs-service/src/main/java/org/apache/sentry/hdfs/SentryHDFSServiceClientDefaultImpl.java b/sentry-hdfs/sentry-hdfs-service/src/main/java/org/apache/sentry/hdfs/SentryHDFSServiceClientDefaultImpl.java
index 9115697..0623652 100644
--- a/sentry-hdfs/sentry-hdfs-service/src/main/java/org/apache/sentry/hdfs/SentryHDFSServiceClientDefaultImpl.java
+++ b/sentry-hdfs/sentry-hdfs-service/src/main/java/org/apache/sentry/hdfs/SentryHDFSServiceClientDefaultImpl.java
@@ -101,6 +101,8 @@
   public SentryAuthzUpdate getAllUpdatesFrom(long permSeqNum, long pathSeqNum, long pathImgNum)
           throws SentryHdfsServiceException {
     try {
+      LOGGER.debug("Requesting updates: Perm sequence num:{}, Path sequence num: {}, Path Image Number: {})",
+              permSeqNum, pathSeqNum, pathImgNum);
       TAuthzUpdateRequest updateRequest = new TAuthzUpdateRequest(permSeqNum, pathSeqNum, pathImgNum);
       TAuthzUpdateResponse sentryUpdates = client.get_authz_updates(updateRequest);
 
@@ -121,8 +123,8 @@
       }
 
       if (LOGGER.isDebugEnabled() && !(permsUpdates.isEmpty() && pathsUpdates.isEmpty()) ) {
-        LOGGER.debug("getAllUpdatesFrom({},{},{}): permsUpdates[{}], pathsUpdates[{}]",
-          new Object[] { permSeqNum, pathSeqNum, pathImgNum, permsUpdates.size(), pathsUpdates.size() });
+        LOGGER.debug("Requesting updates: Perm sequence num:{}, Path sequence num: {}, Path Image Number: {})",
+                permSeqNum, pathSeqNum, pathImgNum);
         if (LOGGER.isTraceEnabled()) {
           if (!permsUpdates.isEmpty()) {
             LOGGER.trace("permsUpdates{}", permsUpdates);