sentry-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From sp...@apache.org
Subject sentry git commit: SENTRY-2040: When getting Snapshots from HMS we need more logging around cases when a snapshot is not being received (Arjun Mishra, reviewed by Sergio Pena, Na Li, Vadim Spector, kalyan kumar kalvagadda)
Date Fri, 08 Dec 2017 15:51:29 GMT
Repository: sentry
Updated Branches:
  refs/heads/master 71daaf037 -> 72be6e755


SENTRY-2040: When getting Snapshots from HMS we need more logging around cases when a snapshot
is not being received (Arjun Mishra, reviewed by Sergio Pena, Na Li, Vadim Spector, kalyan
kumar kalvagadda)


Project: http://git-wip-us.apache.org/repos/asf/sentry/repo
Commit: http://git-wip-us.apache.org/repos/asf/sentry/commit/72be6e75
Tree: http://git-wip-us.apache.org/repos/asf/sentry/tree/72be6e75
Diff: http://git-wip-us.apache.org/repos/asf/sentry/diff/72be6e75

Branch: refs/heads/master
Commit: 72be6e755374b04709ae83fbfa9f1ebed4d84dcb
Parents: 71daaf0
Author: Sergio Pena <sergio.pena@cloudera.com>
Authored: Fri Dec 8 09:47:45 2017 -0600
Committer: Sergio Pena <sergio.pena@cloudera.com>
Committed: Fri Dec 8 09:47:45 2017 -0600

----------------------------------------------------------------------
 .../db/service/persistent/SentryStore.java      |  3 +-
 .../sentry/service/thrift/CounterWait.java      |  5 ++-
 .../sentry/service/thrift/HMSFollower.java      | 33 ++++++++++++++------
 .../sentry/service/thrift/SentryHMSClient.java  | 12 ++++++-
 4 files changed, 40 insertions(+), 13 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/sentry/blob/72be6e75/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/provider/db/service/persistent/SentryStore.java
----------------------------------------------------------------------
diff --git a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/provider/db/service/persistent/SentryStore.java
b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/provider/db/service/persistent/SentryStore.java
index f32a745..c730a03 100644
--- a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/provider/db/service/persistent/SentryStore.java
+++ b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/provider/db/service/persistent/SentryStore.java
@@ -2837,6 +2837,7 @@ public class SentryStore {
           long snapshotID = getCurrentAuthzPathsSnapshotID(pm);
           long nextSnapshotID = snapshotID + 1;
           pm.makePersistent(new MAuthzPathsSnapshotId(nextSnapshotID));
+          LOGGER.info("Attempting to commit new HMS snapshot with ID = {}", nextSnapshotID);
           for (Map.Entry<String, Collection<String>> authzPath : authzPaths.entrySet())
{
             pm.makePersistent(new MAuthzPathsMapping(nextSnapshotID, authzPath.getKey(),
authzPath.getValue()));
           }
@@ -2909,7 +2910,7 @@ public class SentryStore {
         Collection<String> paths) {
     long currentSnapshotID = getCurrentAuthzPathsSnapshotID(pm);
     if (currentSnapshotID <= EMPTY_PATHS_SNAPSHOT_ID) {
-      LOGGER.error("AuthzObj: {} cannot be persisted if an paths snapshot ID does not exist
yet.");
+      LOGGER.warn("AuthzObj: {} cannot be persisted if paths snapshot ID does not exist yet.",
authzObj);
     }
 
     MAuthzPathsMapping mAuthzPathsMapping = getMAuthzPathsMappingCore(pm, currentSnapshotID,
authzObj);

http://git-wip-us.apache.org/repos/asf/sentry/blob/72be6e75/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/CounterWait.java
----------------------------------------------------------------------
diff --git a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/CounterWait.java
b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/CounterWait.java
index 2268ce7..558e695 100644
--- a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/CounterWait.java
+++ b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/CounterWait.java
@@ -130,7 +130,7 @@ public final class CounterWait {
   public synchronized void update(long newValue) {
     // update() is synchronized so the value can't change.
     long oldValue = currentId.get();
-
+    LOGGER.debug("CounterWait update: oldValue = {}, newValue = {}", oldValue, newValue);
     // Avoid doing extra work if not needed
     if (oldValue == newValue) {
       return; // no-op
@@ -160,6 +160,7 @@ public final class CounterWait {
    */
   public synchronized void reset(long newValue) {
     long oldValue = currentId.get();
+    LOGGER.debug("CounterWait reset: oldValue = {}, newValue = {}", oldValue, newValue);
 
     if (newValue > oldValue) {
       update(newValue);
@@ -209,6 +210,7 @@ public final class CounterWait {
     // will not block, so it is safe to wake up before the wait.
     // So sit tight and wait patiently.
     eid.waitFor();
+    LOGGER.debug("CounterWait added new value to waitFor: value = {}, currentId = {}", value,
currentId.get());
     return currentId.get();
   }
 
@@ -238,6 +240,7 @@ public final class CounterWait {
         return;
       }
       // Due for wake-up call
+      LOGGER.debug("CounterWait wakeup: event = {} is less than value = {}", e.getValue(),
value);
       e.wakeup();
     }
   }

http://git-wip-us.apache.org/repos/asf/sentry/blob/72be6e75/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/HMSFollower.java
----------------------------------------------------------------------
diff --git a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/HMSFollower.java
b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/HMSFollower.java
index c1471d1..aa1b6a3 100644
--- a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/HMSFollower.java
+++ b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/HMSFollower.java
@@ -222,7 +222,7 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
       // Continue with processing new notifications if no snapshots are done.
       processNotifications(notifications);
     } catch (TException e) {
-      LOGGER.error("An error occurred while fetching HMS notifications: {}", e.getMessage());
+      LOGGER.error("An error occurred while fetching HMS notifications: ", e);
       close();
     } catch (Throwable t) {
       // catching errors to prevent the executor to halt.
@@ -248,6 +248,8 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
    */
   private boolean isFullSnapshotRequired(long latestSentryNotificationId) throws Exception
{
     if (sentryStore.isHmsNotificationEmpty()) {
+      LOGGER.debug("Sentry Store has no HMS Notifications. Create Full HMS Snapshot. "
+          + "latest sentry notification Id = {}", latestSentryNotificationId);
       return true;
     }
 
@@ -260,8 +262,9 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
 
     long currentHmsNotificationId = notificationFetcher.getCurrentNotificationId();
     if (currentHmsNotificationId < latestSentryNotificationId) {
-      LOGGER.info("The latest notification ID on HMS is less than the latest notification
ID "
-          + "processed by Sentry. Need to request a full HMS snapshot.");
+      LOGGER.info("The current notification ID on HMS = {} is less than the latest processed
Sentry "
+          + "notification ID = {}. Need to request a full HMS snapshot",
+          currentHmsNotificationId, latestSentryNotificationId);
       return true;
     }
 
@@ -313,8 +316,8 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
     long firstNotificationId = eventList.get(0).getEventId();
 
     if (firstNotificationId > (latestProcessedId + 1)) {
-      LOGGER.info("Current HMS notifications are out-of-sync with latest Sentry processed"
-          + "notifications. Need to request a full HMS snapshot.");
+      LOGGER.info("First HMS event notification Id = {} is greater than latest Sentry processed"
+          + "notification Id = {} + 1. Need to request a full HMS snapshot.", firstNotificationId,
latestProcessedId);
       return true;
     }
 
@@ -340,20 +343,23 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
 
       PathsImage snapshotInfo = client.getFullSnapshot();
       if (snapshotInfo.getPathImage().isEmpty()) {
+        LOGGER.debug("Received empty path image from HMS while taking a full snapshot");
         return snapshotInfo.getId();
       }
 
       // Check we're still the leader before persisting the new snapshot
       if (!isLeader()) {
+        LOGGER.info("Not persisting full snapshot since not a leader");
         return SentryStore.EMPTY_NOTIFICATION_ID;
       }
       try {
-        LOGGER.debug("Persisting HMS path full snapshot");
-
         if (hdfsSyncEnabled) {
+          LOGGER.info("Persisting full snapshot for notification Id = {}", snapshotInfo.getId());
           sentryStore.persistFullPathsImage(snapshotInfo.getPathImage(), snapshotInfo.getId());
         } else {
           // We need to persist latest notificationID for next poll
+          LOGGER.info("HDFSSync is disabled. Not Persisting full snapshot, "
+              + "but only setting last processed notification Id = {}", snapshotInfo.getId());
           sentryStore.setLastProcessedNotificationID(snapshotInfo.getId());
         }
       } catch (Exception failure) {
@@ -367,6 +373,9 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
       // Log this message only once
       LOGGER.info("Sentry HMS support is ready");
       return snapshotInfo.getId();
+    } catch(Exception failure) {
+      LOGGER.error("Received exception while creating HMS path full snapshot ");
+      throw failure;
     } finally {
       SentryStateBank
           .disableState(SentryServiceState.COMPONENT, SentryServiceState.FULL_UPDATE_RUNNING);
@@ -391,6 +400,7 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
       try {
         // Only the leader should process the notifications
         if (!isLeader()) {
+          LOGGER.debug("Not processing notifications since not a leader");
           return;
         }
         isNotificationProcessed = notificationProcessor.processNotificationEvent(event);
@@ -414,11 +424,10 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
           // Update the notification ID in the persistent store even when the notification
is
           // not processed as the content in in the notification is not valid.
           // Continue processing the next notification.
-          LOGGER.debug("Explicitly Persisting Notification ID:{}", event.getEventId());
+          LOGGER.debug("Explicitly Persisting Notification ID = {} ", event.getEventId());
           sentryStore.persistLastProcessedNotificationID(event.getEventId());
         } catch (Exception failure) {
-          LOGGER.error("Received exception while persisting the notification ID "
-              + event.getEventId());
+          LOGGER.error("Received exception while persisting the notification ID = {}", event.getEventId());
           throw failure;
         }
       }
@@ -439,6 +448,7 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
   private void wakeUpWaitingClientsForSync(long eventId) {
     CounterWait counterWait = sentryStore.getCounterWait();
 
+    LOGGER.debug("wakeUpWaitingClientsForSync: eventId = {}, hmsImageId = {}", eventId, hmsImageId);
     // Wake up any HMS waiters that are waiting for this ID.
     // counterWait should never be null, but tests mock SentryStore and a mocked one
     // doesn't have it.
@@ -450,6 +460,7 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
     try {
       // Read actual HMS image ID
       lastHMSSnapshotId = sentryStore.getLastProcessedImageID();
+      LOGGER.debug("wakeUpWaitingClientsForSync: lastHMSSnapshotId = {}", lastHMSSnapshotId);
     } catch (Exception e) {
       counterWait.update(eventId);
       LOGGER.error("Failed to get the last processed HMS image id from sentry store");
@@ -460,8 +471,10 @@ public class HMSFollower implements Runnable, AutoCloseable, PubSub.Subscriber
{
     if (lastHMSSnapshotId > hmsImageId) {
       counterWait.reset(eventId);
       hmsImageId = lastHMSSnapshotId;
+      LOGGER.debug("wakeUpWaitingClientsForSync: reset counterWait with eventId = {}, new
hmsImageId = {}", eventId, hmsImageId);
     }
 
+    LOGGER.debug("wakeUpWaitingClientsForSync: update counterWait with eventId = {}, hmsImageId
= {}", eventId, hmsImageId);
     counterWait.update(eventId);
   }
 

http://git-wip-us.apache.org/repos/asf/sentry/blob/72be6e75/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/SentryHMSClient.java
----------------------------------------------------------------------
diff --git a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/SentryHMSClient.java
b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/SentryHMSClient.java
index eccb40f..7e774b4 100644
--- a/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/SentryHMSClient.java
+++ b/sentry-provider/sentry-provider-db/src/main/java/org/apache/sentry/service/thrift/SentryHMSClient.java
@@ -22,6 +22,7 @@ import com.codahale.metrics.Counter;
 import com.codahale.metrics.Timer;
 import com.codahale.metrics.Timer.Context;
 import com.google.common.annotations.VisibleForTesting;
+import org.apache.commons.lang.exception.ExceptionUtils;
 import org.apache.hadoop.conf.Configuration;
 import org.apache.hadoop.hive.metastore.HiveMetaStoreClient;
 import org.apache.hadoop.hive.metastore.api.CurrentNotificationEventId;
@@ -149,6 +150,7 @@ class SentryHMSClient implements AutoCloseable {
       CurrentNotificationEventId eventIdBefore = client.getCurrentNotificationEventId();
       Map<String, Collection<String>> pathsFullSnapshot = fetchFullUpdate();
       if (pathsFullSnapshot.isEmpty()) {
+        LOGGER.info("Received empty paths when getting full snapshot. NotificationID Before
Snapshot: {}", eventIdBefore.getEventId());
         return new PathsImage(pathsFullSnapshot, SentryStore.EMPTY_NOTIFICATION_ID,
             SentryStore.EMPTY_PATHS_SNAPSHOT_ID);
       }
@@ -185,6 +187,7 @@ class SentryHMSClient implements AutoCloseable {
         }
 
         for (NotificationEvent event : response.getEvents()) {
+          LOGGER.info("Received event = {} currentEventId = {}, eventIdAfter = {}", event.getEventId(),
currentEventId, eventIdAfter);
           if (event.getEventId() <= eventIdBefore.getEventId()) {
             LOGGER.error("Received stray event with eventId {} which is less then {}",
                     event.getEventId(), eventIdBefore);
@@ -192,6 +195,7 @@ class SentryHMSClient implements AutoCloseable {
           }
           if (event.getEventId() > eventIdAfter.getEventId()) {
             // Enough events processed
+            LOGGER.debug("Received eventId = {} is greater than eventIdAfter = {}", event.getEventId(),
eventIdAfter);
             break;
           }
           try {
@@ -199,6 +203,11 @@ class SentryHMSClient implements AutoCloseable {
           } catch (Exception e) {
             LOGGER.warn("Failed to apply operation", e);
           }
+
+          //Log warning message if event id increments are not sequential
+          if( event.getEventId() != (currentEventId + 1) ) {
+            LOGGER.warn("Received non-sequential event. currentEventId = {} received eventId
= {} ", currentEventId, event.getEventId());
+          }
           currentEventId = event.getEventId();
         }
       }
@@ -211,7 +220,8 @@ class SentryHMSClient implements AutoCloseable {
           SentryStore.EMPTY_PATHS_SNAPSHOT_ID);
     } catch (TException failure) {
       LOGGER.error("Fetching a new HMS snapshot cannot continue because an error occurred
during "
-          + "the HMS communication: ", failure.getMessage());
+          + "the HMS communication: ", failure);
+      LOGGER.error("Root Exception", ExceptionUtils.getRootCause(failure));
       return new PathsImage(Collections.<String, Collection<String>>emptyMap(),
           SentryStore.EMPTY_NOTIFICATION_ID, SentryStore.EMPTY_PATHS_SNAPSHOT_ID);
     }


Mime
View raw message