Improved node bootstrap and debugging

Change-Id: I37d8a5236c9dc798a524891c8918380a6f85a6b5
diff --git a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/cli/CordVtnNodeCheckCommand.java b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/cli/CordVtnNodeCheckCommand.java
index d6224fb..782003e 100644
--- a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/cli/CordVtnNodeCheckCommand.java
+++ b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/cli/CordVtnNodeCheckCommand.java
@@ -21,6 +21,9 @@
 import org.onosproject.cli.AbstractShellCommand;
 import org.onosproject.cordvtn.api.CordVtnNode;
 import org.onosproject.cordvtn.impl.CordVtnNodeManager;
+import org.onosproject.net.Device;
+import org.onosproject.net.device.DeviceService;
+import org.onosproject.net.driver.DriverService;
 
 /**
  * Checks detailed node init state.
@@ -36,6 +39,8 @@
     @Override
     protected void execute() {
         CordVtnNodeManager nodeManager = AbstractShellCommand.get(CordVtnNodeManager.class);
+        DeviceService deviceService = AbstractShellCommand.get(DeviceService.class);
+
         CordVtnNode node = nodeManager.getNodes()
                 .stream()
                 .filter(n -> n.hostname().equals(hostname))
@@ -48,5 +53,22 @@
         }
 
         print(nodeManager.checkNodeInitState(node));
+
+        print("%n[DEBUG]");
+        Device device = deviceService.getDevice(node.intBrId());
+        String driver = get(DriverService.class).getDriver(device.id()).name();
+        print("%s available=%s driver=%s %s",
+              device.id(),
+              deviceService.isAvailable(device.id()),
+              driver,
+              device.annotations());
+
+        deviceService.getPorts(node.intBrId()).forEach(port -> {
+            Object portIsEnabled = port.isEnabled() ? "enabled" : "disabled";
+            print("port=%s state=%s %s",
+                  port.number(),
+                  portIsEnabled,
+                  port.annotations());
+        });
     }
 }
diff --git a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtn.java b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtn.java
index f816cf9..7f6cc7e 100644
--- a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtn.java
+++ b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtn.java
@@ -178,7 +178,7 @@
 
     @Activate
     protected void activate() {
-        appId = coreService.registerApplication("org.onosproject.cordvtn");
+        appId = coreService.registerApplication(CordVtnService.CORDVTN_APP_ID);
         ruleInstaller = new CordVtnRuleInstaller(appId, flowRuleService,
                                                  deviceService,
                                                  groupService,
diff --git a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtnNodeManager.java b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtnNodeManager.java
index 0b00979..acdd018 100644
--- a/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtnNodeManager.java
+++ b/apps/cordvtn/src/main/java/org/onosproject/cordvtn/impl/CordVtnNodeManager.java
@@ -86,6 +86,7 @@
 import static com.google.common.base.Preconditions.checkNotNull;
 import static java.util.concurrent.Executors.newSingleThreadScheduledExecutor;
 import static org.onlab.util.Tools.groupedThreads;
+import static org.onosproject.cordvtn.impl.RemoteIpCommandUtil.*;
 import static org.onosproject.net.Device.Type.SWITCH;
 import static org.onosproject.net.behaviour.TunnelDescription.Type.VXLAN;
 import static org.slf4j.LoggerFactory.getLogger;
@@ -222,7 +223,7 @@
     }
 
     @Activate
-    protected void active() {
+    protected void activate() {
         appId = coreService.getAppId(CordVtnService.CORDVTN_APP_ID);
         localNodeId = clusterService.getLocalNode().id();
         leadershipService.runForLeadership(appId.name());
@@ -242,18 +243,20 @@
         nodeStore.addListener(nodeStoreListener);
         deviceService.addListener(deviceListener);
         configService.addListener(configListener);
+
+        log.info("Started");
     }
 
     @Deactivate
     protected void deactivate() {
         configService.removeListener(configListener);
         deviceService.removeListener(deviceListener);
-
         nodeStore.removeListener(nodeStoreListener);
-        nodeStore.clear();
 
         leadershipService.withdraw(appId.name());
         eventExecutor.shutdown();
+
+        log.info("Stopped");
     }
 
     /**
@@ -344,29 +347,31 @@
             return null;
         }
 
-        Session session = RemoteIpCommandUtil.connect(node.sshInfo());
+        Session session = connect(node.sshInfo());
         if (session == null) {
             log.debug("Failed to SSH to {}", node.hostname());
             return null;
         }
 
-        Set<IpAddress> intBrIps = RemoteIpCommandUtil.getCurrentIps(session, DEFAULT_BRIDGE);
+        Set<IpAddress> intBrIps = getCurrentIps(session, DEFAULT_BRIDGE);
         String result = String.format(
-                "br-int created and connected : %s (%s)%n" +
-                        "VXLAN interface created : %s%n" +
-                        "Data plane interface added : %s (%s)%n" +
-                        "IP flushed from %s : %s%n" +
+                "Current state : %s%n" +
+                        "br-int created and connected to ONOS : %s (%s)%n" +
+                        "VXLAN interface added to br-int : %s%n" +
+                        "Data plane interface is added to br-int and enabled : %s (%s)%n" +
+                        "IP flushed from data plane interface : %s (%s)%n" +
                         "Data plane IP added to br-int : %s (%s)%n" +
                         "Local management IP added to br-int : %s (%s)",
+                node.state(),
                 isBrIntCreated(node) ? OK : NO, node.intBrId(),
                 isTunnelIntfCreated(node) ? OK : NO,
                 isDataPlaneIntfAdded(node) ? OK : NO, node.dpIntf(),
-                node.dpIntf(),
-                RemoteIpCommandUtil.getCurrentIps(session, node.dpIntf()).isEmpty() ? OK : NO,
+                isInterfaceUp(session, node.dpIntf()) &&
+                        getCurrentIps(session, node.dpIntf()).isEmpty() ? OK : NO, node.dpIntf(),
                 intBrIps.contains(node.dpIp().ip()) ? OK : NO, node.dpIp().cidr(),
                 intBrIps.contains(node.localMgmtIp().ip()) ? OK : NO, node.localMgmtIp().cidr());
 
-        RemoteIpCommandUtil.disconnect(session);
+        disconnect(session);
 
         return result;
     }
@@ -630,6 +635,18 @@
             return;
         }
 
+        Session session = connect(node.sshInfo());
+        if (session == null) {
+            log.debug("Failed to SSH to {}", node.hostname());
+            return;
+        }
+
+        if (!isInterfaceUp(session, node.dpIntf())) {
+            log.warn("Interface {} is not available", node.dpIntf());
+            return;
+        }
+        disconnect(session);
+
         try {
             Device device = deviceService.getDevice(node.ovsdbId());
             if (device.is(BridgeConfig.class)) {
@@ -650,24 +667,24 @@
      * @param node cordvtn node
      */
     private void setIpAddress(CordVtnNode node) {
-        Session session = RemoteIpCommandUtil.connect(node.sshInfo());
+        Session session = connect(node.sshInfo());
         if (session == null) {
             log.debug("Failed to SSH to {}", node.hostname());
             return;
         }
 
-        RemoteIpCommandUtil.getCurrentIps(session, DEFAULT_BRIDGE).stream()
+        getCurrentIps(session, DEFAULT_BRIDGE).stream()
                 .filter(ip -> !ip.equals(node.localMgmtIp().ip()))
                 .filter(ip -> !ip.equals(node.dpIp().ip()))
-                .forEach(ip -> RemoteIpCommandUtil.deleteIp(session, ip, DEFAULT_BRIDGE));
+                .forEach(ip -> deleteIp(session, ip, DEFAULT_BRIDGE));
 
-        boolean result = RemoteIpCommandUtil.flushIp(session, node.dpIntf()) &&
-                RemoteIpCommandUtil.setInterfaceUp(session, node.dpIntf()) &&
-                RemoteIpCommandUtil.addIp(session, node.dpIp(), DEFAULT_BRIDGE) &&
-                RemoteIpCommandUtil.addIp(session, node.localMgmtIp(), DEFAULT_BRIDGE) &&
-                RemoteIpCommandUtil.setInterfaceUp(session, DEFAULT_BRIDGE);
+        boolean result = flushIp(session, node.dpIntf()) &&
+                setInterfaceUp(session, node.dpIntf()) &&
+                addIp(session, node.dpIp(), DEFAULT_BRIDGE) &&
+                addIp(session, node.localMgmtIp(), DEFAULT_BRIDGE) &&
+                setInterfaceUp(session, DEFAULT_BRIDGE);
 
-        RemoteIpCommandUtil.disconnect(session);
+        disconnect(session);
 
         if (result) {
             setNodeState(node, NodeState.COMPLETE);
@@ -720,20 +737,20 @@
      * @return true if the IP is set, false otherwise
      */
     private boolean isIpAddressSet(CordVtnNode node) {
-        Session session = RemoteIpCommandUtil.connect(node.sshInfo());
+        Session session = connect(node.sshInfo());
         if (session == null) {
             log.debug("Failed to SSH to {}", node.hostname());
             return false;
         }
 
-        Set<IpAddress> intBrIps = RemoteIpCommandUtil.getCurrentIps(session, DEFAULT_BRIDGE);
-        boolean result = RemoteIpCommandUtil.getCurrentIps(session, node.dpIntf()).isEmpty() &&
-                RemoteIpCommandUtil.isInterfaceUp(session, node.dpIntf()) &&
+        Set<IpAddress> intBrIps = getCurrentIps(session, DEFAULT_BRIDGE);
+        boolean result = getCurrentIps(session, node.dpIntf()).isEmpty() &&
+                isInterfaceUp(session, node.dpIntf()) &&
                 intBrIps.contains(node.dpIp().ip()) &&
                 intBrIps.contains(node.localMgmtIp().ip()) &&
-                RemoteIpCommandUtil.isInterfaceUp(session, DEFAULT_BRIDGE);
+                isInterfaceUp(session, DEFAULT_BRIDGE);
 
-        RemoteIpCommandUtil.disconnect(session);
+        disconnect(session);
         return result;
     }
 
@@ -951,13 +968,13 @@
                     oldNode = event.oldValue().value();
                     newNode = event.newValue().value();
 
+                    log.info("Reloaded {}", newNode.hostname());
                     if (!newNode.equals(oldNode)) {
-                        log.info("{} has been updated", newNode.hostname());
                         log.debug("New node: {}", newNode);
                     }
-                    // perform init procedure based on current state on any updates,
-                    // insert, or even if the node is the same for robustness since
-                    // it's no harm to run the init procedure multiple times
+                    // performs init procedure even if the node is not changed
+                    // for robustness since it's no harm to run init procedure
+                    // multiple times
                     eventExecutor.execute(() -> initNode(newNode));
                     break;
                 case INSERT:
@@ -967,7 +984,7 @@
                     break;
                 case REMOVE:
                     oldNode = event.oldValue().value();
-                    log.info("{} is removed", oldNode.hostname());
+                    log.info("Removed {}", oldNode.hostname());
                     break;
                 default:
                     break;