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 <[email protected]> Authored: Fri Dec 8 09:47:45 2017 -0600 Committer: Sergio Pena <[email protected]> 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); }
