From 818f2e0fdb8706f95de5411f45c1dc7d30e93e33 Mon Sep 17 00:00:00 2001 From: Tom Pantelis Date: Thu, 29 Oct 2015 15:20:38 -0400 Subject: [PATCH] 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 --- .../persist/impl/ConfigPusherImpl.java | 30 +++++++++++++------ .../impl/osgi/ConfigPersisterActivator.java | 8 ++++- .../impl/osgi/ConfigPersisterTest.java | 26 +++++++++++----- 3 files changed, 47 insertions(+), 17 deletions(-) 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 c41a2f4d16..4a0873308c 100644 --- 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> queue = new LinkedBlockingQueue>(QUEUE_SIZE); + private final BlockingQueue> queue = new LinkedBlockingQueue<>(QUEUE_SIZE); public ConfigPusherImpl(NetconfOperationServiceFactory configNetconfConnector, long maxWaitForCapabilitiesMillis, long conflictingVersionTimeoutMillis) { @@ -72,6 +72,7 @@ public class ConfigPusherImpl implements ConfigPusher { List 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 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 missingCaps; + private final Set missingCaps; private NotEnoughCapabilitiesException(String message, Set 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 b27bec3c83..fbcb12e3b3 100644 --- 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 b998b9eff0..50f182090f 100644 --- 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(); } } -- 2.36.6