Bug 4560: Improve config system logging for debuggability

When a config push fails, most of the exceptions that are thrown are
unchecked (like IllegalArgumentEx) and they aren't explicitly caught
so they propagate to the top-level ConfigPersisterActivator thread and
got printed to syserr. So I added a catch and logged to error.

I also added context to the logged message which outputs the xml file
name to aid in debugging issues.

I also added info logging when a config push starts and when it
successfully completes to further aid in debugging issues.

Change-Id: I3db9dcad3cba0abd58c045bc1047e08d6f19ccd3
Signed-off-by: Tom Pantelis <tpanteli@brocade.com>

diff --git a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusherImpl.java b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusherImpl.java
index c41a2f4d16b7e325e228704d58f6e63f798a1700..4a0873308c0a499b3edc0b60d227e7c800d77440 100644 (file)
--- a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusherImpl.java
+++ b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusherImpl.java
@@ -9,7 +9,7 @@
 package org.opendaylight.controller.netconf.persist.impl;
 
 import static com.google.common.base.Preconditions.checkNotNull;
-
+import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Function;
 import com.google.common.base.Stopwatch;
 import com.google.common.collect.Collections2;
@@ -59,7 +59,7 @@ public class ConfigPusherImpl implements ConfigPusher {
     private final long conflictingVersionTimeoutMillis;
     private final NetconfOperationServiceFactory configNetconfConnector;
     private static final int QUEUE_SIZE = 100;
-    private BlockingQueue<List<? extends ConfigSnapshotHolder>> queue = new LinkedBlockingQueue<List<? extends ConfigSnapshotHolder>>(QUEUE_SIZE);
+    private final BlockingQueue<List<? extends ConfigSnapshotHolder>> queue = new LinkedBlockingQueue<>(QUEUE_SIZE);
 
     public ConfigPusherImpl(NetconfOperationServiceFactory configNetconfConnector, long maxWaitForCapabilitiesMillis,
                         long conflictingVersionTimeoutMillis) {
@@ -72,6 +72,7 @@ public class ConfigPusherImpl implements ConfigPusher {
         List<? extends ConfigSnapshotHolder> configs;
         while(true) {
             configs = queue.take();
+
             try {
                 internalPushConfigs(configs);
                 ConfigPersisterNotificationHandler jmxNotificationHandler = new ConfigPersisterNotificationHandler(platformMBeanServer, persisterAggregator);
@@ -80,13 +81,14 @@ public class ConfigPusherImpl implements ConfigPusher {
                 }
 
                 LOG.debug("ConfigPusher has pushed configs {}", configs);
-            } catch (NetconfDocumentedException e) {
-                LOG.error("Error pushing configs {}",configs);
-                throw new IllegalStateException(e);
+            } catch (Exception e) {
+                LOG.debug("Failed to push some of configs: {}", configs, e);
+                break;
             }
         }
     }
 
+    @Override
     public void pushConfigs(List<? extends ConfigSnapshotHolder> configs) throws InterruptedException {
         LOG.debug("Requested to push configs {}", configs);
         this.queue.put(configs);
@@ -98,15 +100,20 @@ public class ConfigPusherImpl implements ConfigPusher {
         // start pushing snapshots:
         for (ConfigSnapshotHolder configSnapshotHolder : configs) {
             if(configSnapshotHolder != null) {
+                LOG.info("Pushing configuration snapshot {}", configSnapshotHolder);
                 EditAndCommitResponse editAndCommitResponseWithRetries = null;
                 try {
                     editAndCommitResponseWithRetries = pushConfigWithConflictingVersionRetries(configSnapshotHolder);
                 } catch (ConfigSnapshotFailureException e) {
-                    LOG.warn("Failed to apply configuration snapshot: {}. Config snapshot is not semantically correct and will be IGNORED. " +
+                    LOG.error("Failed to apply configuration snapshot: {}. Config snapshot is not semantically correct and will be IGNORED. " +
                             "for detailed information see enclosed exception.", e.getConfigIdForReporting(), e);
-                    throw new IllegalStateException("Failed to apply configuration snapshot " + e.getConfigIdForReporting(), e);
+                    onFailedConfigPush("Failed to apply configuration snapshot " + e.getConfigIdForReporting(), e);
+                } catch (Exception e) {
+                    LOG.error("Failed to apply configuration snapshot: {}", configSnapshotHolder, e);
+                    onFailedConfigPush("Failed to apply configuration snapshot " + configSnapshotHolder, e);
                 }
-                LOG.debug("Config snapshot pushed successfully: {}, result: {}", configSnapshotHolder, result);
+
+                LOG.info("Successfully pushed configuration snapshot {}", configSnapshotHolder);
                 result.put(configSnapshotHolder, editAndCommitResponseWithRetries);
             }
         }
@@ -114,6 +121,11 @@ public class ConfigPusherImpl implements ConfigPusher {
         return result;
     }
 
+    @VisibleForTesting
+    protected void onFailedConfigPush(String message, Exception cause) {
+        throw new IllegalStateException(message, cause);
+    }
+
     /**
      * First calls {@link #getOperationServiceWithRetries(java.util.Set, String)} in order to wait until
      * expected capabilities are present, then tries to push configuration. If {@link ConflictingVersionException}
@@ -188,7 +200,7 @@ public class ConfigPusherImpl implements ConfigPusher {
 
     private static class NotEnoughCapabilitiesException extends ConfigPusherException {
         private static final long serialVersionUID = 1L;
-        private Set<String> missingCaps;
+        private final Set<String> missingCaps;
 
         private NotEnoughCapabilitiesException(String message, Set<String> missingCaps) {
             super(message);

diff --git a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterActivator.java b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterActivator.java
index b27bec3c83801a275810e689e0daabbd7b458f47..fbcb12e3b34026c383442e1172af7fdcd0647820 100644 (file)
--- a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterActivator.java
+++ b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterActivator.java
@@ -164,7 +164,7 @@ public class ConfigPersisterActivator implements BundleActivator {
 
             LOG.debug("Creating new job queue");
 
-            final ConfigPusherImpl configPusher = new ConfigPusherImpl(service, maxWaitForCapabilitiesMillis, conflictingVersionTimeoutMillis);
+            final ConfigPusherImpl configPusher = newConfigPusher(service, maxWaitForCapabilitiesMillis, conflictingVersionTimeoutMillis);
             LOG.debug("Configuration Persister got {}", service);
             LOG.debug("Context was {}", context);
             LOG.debug("Registration was {}", registration);
@@ -211,5 +211,11 @@ public class ConfigPersisterActivator implements BundleActivator {
         }
 
     }
+
+    @VisibleForTesting
+    protected ConfigPusherImpl newConfigPusher(NetconfOperationServiceFactory service, long maxWaitForCapabilitiesMillis,
+            long conflictingVersionTimeoutMillis) {
+        return new ConfigPusherImpl(service, maxWaitForCapabilitiesMillis, conflictingVersionTimeoutMillis);
+    }
 }
 

diff --git a/opendaylight/netconf/config-persister-impl/src/test/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterTest.java b/opendaylight/netconf/config-persister-impl/src/test/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterTest.java
index b998b9eff0bee8d9e2224104a9bd0f09491f3701..50f182090f3425f1d55004390e58f9e0976868bd 100644 (file)
--- a/opendaylight/netconf/config-persister-impl/src/test/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterTest.java
+++ b/opendaylight/netconf/config-persister-impl/src/test/java/org/opendaylight/controller/netconf/persist/impl/osgi/ConfigPersisterTest.java
@@ -25,6 +25,8 @@ import org.opendaylight.controller.netconf.mapping.api.HandlingPriority;
 import org.opendaylight.controller.netconf.mapping.api.NetconfOperation;
 import org.opendaylight.controller.netconf.mapping.api.NetconfOperationChainedExecution;
 import org.opendaylight.controller.netconf.mapping.api.NetconfOperationService;
+import org.opendaylight.controller.netconf.mapping.api.NetconfOperationServiceFactory;
+import org.opendaylight.controller.netconf.persist.impl.ConfigPusherImpl;
 import org.opendaylight.controller.netconf.persist.impl.osgi.MockedBundleContext.DummyAdapterWithInitialSnapshot;
 import org.opendaylight.controller.netconf.util.xml.XmlUtil;
 import org.slf4j.Logger;
@@ -42,7 +44,20 @@ public class ConfigPersisterTest {
     private void setUpContext(String requiredCapability) throws Exception {
         DummyAdapterWithInitialSnapshot.expectedCapability = requiredCapability;
         ctx = new MockedBundleContext(1000, 1000);
-        configPersisterActivator = new ConfigPersisterActivator();
+        configPersisterActivator = new ConfigPersisterActivator() {
+            @Override
+            protected ConfigPusherImpl newConfigPusher(NetconfOperationServiceFactory service,
+                    long maxWaitForCapabilitiesMillis, long conflictingVersionTimeoutMillis) {
+                return new ConfigPusherImpl(service, maxWaitForCapabilitiesMillis, conflictingVersionTimeoutMillis) {
+                    @Override
+                    protected void onFailedConfigPush(String message, Exception cause) {
+                        handler.uncaughtException(Thread.currentThread(), cause);
+                        super.onFailedConfigPush(message, cause);
+                    }
+
+                };
+            }
+        };
     }
 
     private void setUpContextAndStartPersister(String requiredCapability, final NetconfOperationService conflictingService) throws Exception {
@@ -54,12 +69,10 @@ public class ConfigPersisterTest {
     @Before
     public void setUp() {
         handler = new TestingExceptionHandler();
-        Thread.setDefaultUncaughtExceptionHandler(handler);
     }
 
     @After
     public void tearDown() throws Exception {
-        Thread.setDefaultUncaughtExceptionHandler(null);
         configPersisterActivator.stop(ctx.getBundleContext());
     }
 
@@ -75,7 +88,7 @@ public class ConfigPersisterTest {
     public void testPersisterSuccessfulPush() throws Exception {
         setUpContextAndStartPersister("cap1", getWorkingService(getOKDocument()));
         Thread.sleep(2000);
-        assertCannotRegisterAsJMXListener_pushWasSuccessful();
+        handler.assertNoException();
     }
 
     // this means pushing of config was successful
@@ -141,9 +154,8 @@ public class ConfigPersisterTest {
             doReturn(workingService).when(ctx.serviceFactory).createService(anyString());
 
         configPersisterActivator.start(ctx.getBundleContext());
-
-        Thread.sleep(1000);
-        assertCannotRegisterAsJMXListener_pushWasSuccessful();
+        Thread.sleep(2000);
+        handler.assertNoException();
     }
 
 }