[ASTERIXDB-1992][ING] Reduce logging level for active events
- user model changes: no
- storage format changes: no
- interface changes: no
Change-Id: Ic3f8e406cfd0d5a5926703bd50de44d9213a41df
Reviewed-on: https://asterix-gerrit.ics.uci.edu/1903
Sonar-Qube: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Tested-by: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
BAD: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Integration-Tests: Jenkins <jenkins@fulliautomatix.ics.uci.edu>
Reviewed-by: Murtadha Hubail <mhubail@apache.org>
diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveEntityEventsListener.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveEntityEventsListener.java
index caf4bec..995e372 100644
--- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveEntityEventsListener.java
+++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveEntityEventsListener.java
@@ -130,7 +130,7 @@
}
protected synchronized void setState(ActivityState newState) {
- LOGGER.log(Level.WARNING, "State is being set to " + newState + " from " + state);
+ LOGGER.log(Level.FINE, "State is being set to " + newState + " from " + state);
this.prevState = state;
this.state = newState;
if (newState == ActivityState.SUSPENDED) {
@@ -142,7 +142,7 @@
@Override
public synchronized void notify(ActiveEvent event) {
try {
- LOGGER.warning("EventListener is notified.");
+ LOGGER.fine("EventListener is notified.");
ActiveEvent.Kind eventKind = event.getEventKind();
switch (eventKind) {
case JOB_CREATED:
@@ -158,7 +158,7 @@
handle((ActivePartitionMessage) event.getEventObject());
break;
default:
- LOGGER.log(Level.WARNING, "Unhandled feed event notification: " + event);
+ LOGGER.log(Level.FINE, "Unhandled feed event notification: " + event);
break;
}
notifySubscribers(event);
@@ -271,10 +271,10 @@
@SuppressWarnings("unchecked")
@Override
public void refreshStats(long timeout) throws HyracksDataException {
- LOGGER.log(Level.WARNING, "refreshStats called");
+ LOGGER.log(Level.FINE, "refreshStats called");
synchronized (this) {
if (state != ActivityState.RUNNING || isFetchingStats) {
- LOGGER.log(Level.WARNING,
+ LOGGER.log(Level.FINE,
"returning immediately since state = " + state + " and fetchingStats = " + isFetchingStats);
return;
} else {
@@ -348,33 +348,32 @@
@Override
public synchronized void recover() throws HyracksDataException {
- LOGGER.log(Level.WARNING, "Recover is called on " + entityId);
+ LOGGER.log(Level.FINE, "Recover is called on " + entityId);
if (recoveryTask != null) {
- LOGGER.log(Level.WARNING,
- "But recovery task for " + entityId + " is already there!! throwing an exception");
+ LOGGER.log(Level.FINE, "But recovery task for " + entityId + " is already there!! throwing an exception");
throw new RuntimeDataException(ErrorCode.DOUBLE_RECOVERY_ATTEMPTS);
}
if (retryPolicyFactory == NoRetryPolicyFactory.INSTANCE) {
- LOGGER.log(Level.WARNING, "But it has no recovery policy, so it is set to permanent failure");
+ LOGGER.log(Level.FINE, "But it has no recovery policy, so it is set to permanent failure");
setState(ActivityState.PERMANENTLY_FAILED);
} else {
ExecutorService executor = appCtx.getServiceContext().getControllerService().getExecutor();
IRetryPolicy policy = retryPolicyFactory.create(this);
cancelRecovery = false;
setState(ActivityState.TEMPORARILY_FAILED);
- LOGGER.log(Level.WARNING, "Recovery task has been submitted");
+ LOGGER.log(Level.FINE, "Recovery task has been submitted");
recoveryTask = executor.submit(() -> doRecover(policy));
}
}
protected Void doRecover(IRetryPolicy policy)
throws AlgebricksException, HyracksDataException, InterruptedException {
- LOGGER.log(Level.WARNING, "Actual Recovery task has started");
+ LOGGER.log(Level.FINE, "Actual Recovery task has started");
if (getState() != ActivityState.TEMPORARILY_FAILED) {
- LOGGER.log(Level.WARNING, "but its state is not temp failure and so we're just returning");
+ LOGGER.log(Level.FINE, "but its state is not temp failure and so we're just returning");
return null;
}
- LOGGER.log(Level.WARNING, "calling the policy");
+ LOGGER.log(Level.FINE, "calling the policy");
while (policy.retry()) {
synchronized (this) {
if (cancelRecovery) {
@@ -516,10 +515,10 @@
WaitForStateSubscriber subscriber;
Future<Void> suspendTask;
synchronized (this) {
- LOGGER.log(Level.WARNING, "suspending entity " + entityId);
- LOGGER.log(Level.WARNING, "Waiting for ongoing activities");
+ LOGGER.log(Level.FINE, "suspending entity " + entityId);
+ LOGGER.log(Level.FINE, "Waiting for ongoing activities");
waitForNonTransitionState();
- LOGGER.log(Level.WARNING, "Proceeding with suspension. Current state is " + state);
+ LOGGER.log(Level.FINE, "Proceeding with suspension. Current state is " + state);
if (state == ActivityState.STOPPED || state == ActivityState.PERMANENTLY_FAILED) {
suspended = true;
return;
@@ -537,12 +536,12 @@
EnumSet.of(ActivityState.SUSPENDED, ActivityState.TEMPORARILY_FAILED));
suspendTask = metadataProvider.getApplicationContext().getServiceContext().getControllerService()
.getExecutor().submit(() -> doSuspend(metadataProvider));
- LOGGER.log(Level.WARNING, "Suspension task has been submitted");
+ LOGGER.log(Level.FINE, "Suspension task has been submitted");
}
try {
- LOGGER.log(Level.WARNING, "Waiting for suspension task to complete");
+ LOGGER.log(Level.FINE, "Waiting for suspension task to complete");
suspendTask.get();
- LOGGER.log(Level.WARNING, "waiting for state to become SUSPENDED or TEMPORARILY_FAILED");
+ LOGGER.log(Level.FINE, "waiting for state to become SUSPENDED or TEMPORARILY_FAILED");
subscriber.sync();
} catch (Exception e) {
synchronized (this) {
diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveNotificationHandler.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveNotificationHandler.java
index b34d011..c5e5dbb 100644
--- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveNotificationHandler.java
+++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveNotificationHandler.java
@@ -73,13 +73,13 @@
EntityId entityId = jobId2EntityId.get(event.getJobId());
if (entityId != null) {
IActiveEntityEventsListener listener = entityEventListeners.get(entityId);
- LOGGER.log(Level.WARNING, "Next event is of type " + event.getEventKind());
+ LOGGER.log(Level.FINE, "Next event is of type " + event.getEventKind());
if (event.getEventKind() == Kind.JOB_FINISHED) {
- LOGGER.log(Level.WARNING, "Removing the job");
+ LOGGER.log(Level.FINE, "Removing the job");
jobId2EntityId.remove(event.getJobId());
}
if (listener != null) {
- LOGGER.log(Level.WARNING, "Notifying the listener");
+ LOGGER.log(Level.FINE, "Notifying the listener");
listener.notify(event);
}
} else {
@@ -91,17 +91,17 @@
@Override
public void notifyJobCreation(JobId jobId, JobSpecification jobSpecification) throws HyracksDataException {
- LOGGER.log(Level.WARNING,
+ LOGGER.log(Level.FINE,
"notifyJobCreation(JobId jobId, JobSpecification jobSpecification) was called with jobId = " + jobId);
Object property = jobSpecification.getProperty(ACTIVE_ENTITY_PROPERTY_NAME);
if (property == null || !(property instanceof EntityId)) {
- LOGGER.log(Level.WARNING, "Job is not of type active job. property found to be: " + property);
+ LOGGER.log(Level.FINE, "Job is not of type active job. property found to be: " + property);
return;
}
EntityId entityId = (EntityId) property;
monitorJob(jobId, entityId);
boolean found = jobId2EntityId.get(jobId) != null;
- LOGGER.log(Level.WARNING, "Job was found to be: " + (found ? "Active" : "Inactive"));
+ LOGGER.log(Level.FINE, "Job was found to be: " + (found ? "Active" : "Inactive"));
add(new ActiveEvent(jobId, Kind.JOB_CREATED, entityId, jobSpecification));
}
@@ -120,7 +120,7 @@
LOGGER.log(Level.WARNING, "monitoring started for job id: " + jobId);
}
} else {
- LOGGER.severe("No listener was found for the entity: " + entityId);
+ LOGGER.info("No listener was found for the entity: " + entityId);
}
jobId2EntityId.put(jobId, entityId);
}
@@ -194,7 +194,7 @@
if (suspended) {
throw new RuntimeDataException(ErrorCode.ACTIVE_NOTIFICATION_HANDLER_IS_SUSPENDED);
}
- LOGGER.log(Level.WARNING, "unregisterListener(IActiveEntityEventsListener listener) was called for the entity "
+ LOGGER.log(Level.FINE, "unregisterListener(IActiveEntityEventsListener listener) was called for the entity "
+ listener.getEntityId());
IActiveEntityEventsListener registeredListener = entityEventListeners.remove(listener.getEntityId());
if (registeredListener == null) {
@@ -221,16 +221,16 @@
@Override
public synchronized void recover() throws HyracksDataException {
- LOGGER.log(Level.WARNING, "Starting active recovery");
+ LOGGER.log(Level.FINE, "Starting active recovery");
for (IActiveEntityEventsListener listener : entityEventListeners.values()) {
synchronized (listener) {
- LOGGER.log(Level.WARNING, "Entity " + listener.getEntityId() + " is " + listener.getStats());
+ LOGGER.log(Level.FINE, "Entity " + listener.getEntityId() + " is " + listener.getStats());
if (listener.getState() == ActivityState.PERMANENTLY_FAILED
&& listener instanceof IActiveEntityController) {
- LOGGER.log(Level.WARNING, "Recovering");
+ LOGGER.log(Level.FINE, "Recovering");
((IActiveEntityController) listener).recover();
} else {
- LOGGER.log(Level.WARNING, "Only notifying");
+ LOGGER.log(Level.FINE, "Only notifying");
listener.notifyAll();
}
}
@@ -243,7 +243,7 @@
if (suspended) {
throw new RuntimeDataException(ErrorCode.ACTIVE_EVENT_HANDLER_ALREADY_SUSPENDED);
}
- LOGGER.log(Level.WARNING, "Suspending active events handler");
+ LOGGER.log(Level.FINE, "Suspending active events handler");
suspended = true;
}
IMetadataLockManager lockManager = mdProvider.getApplicationContext().getMetadataLockManager();
@@ -253,27 +253,27 @@
// exclusive lock all the datasets
String dataverseName = listener.getEntityId().getDataverse();
String entityName = listener.getEntityId().getEntityName();
- LOGGER.log(Level.WARNING, "Suspending " + listener.getEntityId());
- LOGGER.log(Level.WARNING, "Acquiring locks");
+ LOGGER.log(Level.FINE, "Suspending " + listener.getEntityId());
+ LOGGER.log(Level.FINE, "Acquiring locks");
lockManager.acquireActiveEntityWriteLock(mdProvider.getLocks(), dataverseName + '.' + entityName);
List<Dataset> datasets = ((ActiveEntityEventsListener) listener).getDatasets();
for (Dataset dataset : datasets) {
lockManager.acquireDatasetExclusiveModificationLock(mdProvider.getLocks(),
DatasetUtil.getFullyQualifiedName(dataset));
}
- LOGGER.log(Level.WARNING, "locks acquired");
+ LOGGER.log(Level.FINE, "locks acquired");
((ActiveEntityEventsListener) listener).suspend(mdProvider);
- LOGGER.log(Level.WARNING, listener.getEntityId() + " suspended");
+ LOGGER.log(Level.FINE, listener.getEntityId() + " suspended");
}
}
public void resume(MetadataProvider mdProvider)
throws AsterixException, HyracksDataException, InterruptedException {
- LOGGER.log(Level.WARNING, "Resuming active events handler");
+ LOGGER.log(Level.FINE, "Resuming active events handler");
for (IActiveEntityEventsListener listener : entityEventListeners.values()) {
- LOGGER.log(Level.WARNING, "Resuming " + listener.getEntityId());
+ LOGGER.log(Level.FINE, "Resuming " + listener.getEntityId());
((ActiveEntityEventsListener) listener).resume(mdProvider);
- LOGGER.log(Level.WARNING, listener.getEntityId() + " resumed");
+ LOGGER.log(Level.FINE, listener.getEntityId() + " resumed");
}
synchronized (this) {
suspended = false;