From: Tomas Olvecky <tolvecky@cisco.com>
Date: Tue, 10 Dec 2013 15:58:33 +0000 (+0100)
Subject: Improve logging of persister and netconf client.
X-Git-Tag: jenkins-controller-bulk-release-prepare-only-2-1~207^2
X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?p=controller.git;a=commitdiff_plain;h=9e85156750c913457315e6593adfa362e1a443cf

Improve logging of persister and netconf client.

Add a debug message measuring time spent waiting for netconf server to reply in NetconfClient.
Log with error level failure to send/recieve netconf message in config-persister-impl.
Add TODOs to config-manager's dependency resolver for detecting cycles.

Change-Id: I412abad141b40eb9346ef404d2efeba8c197e018
Signed-off-by: Tomas Olvecky <tolvecky@cisco.com>
---

diff --git a/opendaylight/config/config-manager/src/main/java/org/opendaylight/controller/config/manager/impl/dependencyresolver/DependencyResolverImpl.java b/opendaylight/config/config-manager/src/main/java/org/opendaylight/controller/config/manager/impl/dependencyresolver/DependencyResolverImpl.java
index 065a0f843f..760fe50e28 100644
--- a/opendaylight/config/config-manager/src/main/java/org/opendaylight/controller/config/manager/impl/dependencyresolver/DependencyResolverImpl.java
+++ b/opendaylight/config/config-manager/src/main/java/org/opendaylight/controller/config/manager/impl/dependencyresolver/DependencyResolverImpl.java
@@ -48,6 +48,7 @@ final class DependencyResolverImpl implements DependencyResolver,
     /**
      * {@inheritDoc}
      */
+    //TODO: check for cycles
     @Override
     public void validateDependency(
             Class<? extends AbstractServiceInterface> expectedServiceInterface,
@@ -101,6 +102,7 @@ final class DependencyResolverImpl implements DependencyResolver,
     /**
      * {@inheritDoc}
      */
+    //TODO: check for cycles
     @Override
     public <T> T resolveInstance(Class<T> expectedType, ObjectName dependentON,
             JmxAttribute jmxAttribute) {
diff --git a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusher.java b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusher.java
index 044346e2c5..89c2703285 100644
--- a/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusher.java
+++ b/opendaylight/netconf/config-persister-impl/src/main/java/org/opendaylight/controller/netconf/persist/impl/ConfigPusher.java
@@ -169,7 +169,7 @@ public class ConfigPusher {
         NetconfMessage message = createEditConfigMessage(xmlToBePersisted, "/netconfOp/editConfig.xml");
 
         // sending message to netconf
-        NetconfMessage responseMessage = netconfClient.sendMessage(message, NETCONF_SEND_ATTEMPTS, NETCONF_SEND_ATTEMPT_MS_DELAY);
+        NetconfMessage responseMessage = getResponse(message, netconfClient);
 
         XmlElement element = XmlElement.fromDomDocument(responseMessage.getDocument());
         Preconditions.checkState(element.getName().equals(XmlNetconfConstants.RPC_REPLY_KEY));
@@ -178,7 +178,7 @@ public class ConfigPusher {
         Util.checkIsOk(element, responseMessage);
         response.append(XmlUtil.toString(responseMessage.getDocument()));
         response.append("}");
-        responseMessage = netconfClient.sendMessage(getNetconfMessageFromResource("/netconfOp/commit.xml"), NETCONF_SEND_ATTEMPTS, NETCONF_SEND_ATTEMPT_MS_DELAY);
+        responseMessage = getResponse(getNetconfMessageFromResource("/netconfOp/commit.xml"), netconfClient);
 
         element = XmlElement.fromDomDocument(responseMessage.getDocument());
         Preconditions.checkState(element.getName().equals(XmlNetconfConstants.RPC_REPLY_KEY));
@@ -192,6 +192,15 @@ public class ConfigPusher {
         logger.trace("Detailed message {}", response);
     }
 
+    private static NetconfMessage getResponse(NetconfMessage request, NetconfClient netconfClient) {
+        try {
+            return netconfClient.sendMessage(request, NETCONF_SEND_ATTEMPTS, NETCONF_SEND_ATTEMPT_MS_DELAY);
+        } catch(RuntimeException e) {
+            logger.error("Error while sending message {} to {}", request, netconfClient);
+            throw e;
+        }
+    }
+
     private static NetconfMessage createEditConfigMessage(Element dataElement, String editConfigResourcename) {
         try (InputStream stream = ConfigPersisterNotificationHandler.class.getResourceAsStream(editConfigResourcename)) {
             Preconditions.checkNotNull(stream, "Unable to load resource " + editConfigResourcename);
diff --git a/opendaylight/netconf/netconf-client/src/main/java/org/opendaylight/controller/netconf/client/NetconfClient.java b/opendaylight/netconf/netconf-client/src/main/java/org/opendaylight/controller/netconf/client/NetconfClient.java
index 95f526b2ec..2ce779a1f5 100644
--- a/opendaylight/netconf/netconf-client/src/main/java/org/opendaylight/controller/netconf/client/NetconfClient.java
+++ b/opendaylight/netconf/netconf-client/src/main/java/org/opendaylight/controller/netconf/client/NetconfClient.java
@@ -88,6 +88,7 @@ public class NetconfClient implements Closeable {
     }
 
     public NetconfMessage sendMessage(NetconfMessage message, int attempts, int attemptMsDelay) {
+        long startTime = System.currentTimeMillis();
         Preconditions.checkState(clientSession.isUp(), "Session was not up yet");
         clientSession.sendMessage(message);
         try {
@@ -96,6 +97,9 @@ public class NetconfClient implements Closeable {
             throw new RuntimeException(this + " Cannot read message from " + address, e);
         } catch (IllegalStateException e) {
             throw new IllegalStateException(this + " Cannot read message from " + address, e);
+        } finally {
+            long diffMillis = System.currentTimeMillis() - startTime;
+            logger.debug("Total time spent waiting for response {}", diffMillis);
         }
     }