Repository: asterixdb Updated Branches: refs/heads/master a85f4121f -> 8b077a536
[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 <[email protected]> Tested-by: Jenkins <[email protected]> BAD: Jenkins <[email protected]> Integration-Tests: Jenkins <[email protected]> Reviewed-by: Murtadha Hubail <[email protected]> Project: http://git-wip-us.apache.org/repos/asf/asterixdb/repo Commit: http://git-wip-us.apache.org/repos/asf/asterixdb/commit/8b077a53 Tree: http://git-wip-us.apache.org/repos/asf/asterixdb/tree/8b077a53 Diff: http://git-wip-us.apache.org/repos/asf/asterixdb/diff/8b077a53 Branch: refs/heads/master Commit: 8b077a536aa7c1bb69f31067ace8f136ffdf5182 Parents: a85f412 Author: Abdullah Alamoudi <[email protected]> Authored: Thu Jul 27 00:01:40 2017 -0700 Committer: Murtadha Hubail <[email protected]> Committed: Thu Jul 27 02:15:38 2017 -0700 ---------------------------------------------------------------------- .../app/active/ActiveEntityEventsListener.java | 37 +++++++++--------- .../app/active/ActiveNotificationHandler.java | 40 ++++++++++---------- 2 files changed, 38 insertions(+), 39 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/asterixdb/blob/8b077a53/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveEntityEventsListener.java ---------------------------------------------------------------------- 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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl } 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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl @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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl 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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl @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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl @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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl 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 @@ public abstract class ActiveEntityEventsListener implements IActiveEntityControl 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) { http://git-wip-us.apache.org/repos/asf/asterixdb/blob/8b077a53/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/active/ActiveNotificationHandler.java ---------------------------------------------------------------------- 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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active 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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active @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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active 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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active 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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active @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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active 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 @@ public class ActiveNotificationHandler extends SingleThreadEventProcessor<Active // 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;
