You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@sentry.apache.org by sp...@apache.org on 2017/12/08 15:51:29 UTC
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)
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 <se...@cloudera.com>
Authored: Fri Dec 8 09:47:45 2017 -0600
Committer: Sergio Pena <se...@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);
}