Optimize call flow to complete loopback adapter creation (#408)

Loopback adapter creation operation comprises of two operations - createInterface and setWeakHostOnInterface. These operations take place inside the lock. If there are simultaneous requests, it interleaves these calls causing every loopback adapter creation to absorb the delay due to interleaving. createInterface can take time in seconds (typically 2 to 7 seconds based on the tests) while setWeakHostOnInterface finishes very quickly ( less than a second ). This change calls setWeakHostOnInterface within the same lock if createInterface succeeds. The tests show this improves the loopback adapter creation times for simultaneous requests.

Author: ashvindeodhar

Makefile

@@ -43,6 +43,7 @@ CNSFILES = \
 	$(wildcard cns/restserver/*.go) \
 	$(wildcard cns/routes/*.go) \
 	$(wildcard cns/service/*.go) \
+	$(wildcard cns/networkcontainers/*.go) \
 	$(COREFILES) \
 	$(CNMFILES)
 

cns/networkcontainers/networkcontainers.go

@@ -55,38 +55,42 @@ func NewNetPluginConfiguration(binPath, configPath string) *NetPluginConfigurati
 func interfaceExists(iFaceName string) (bool, error) {
 	_, err := net.InterfaceByName(iFaceName)
 	if err != nil {
-		errMsg := fmt.Sprintf("[Azure CNS] Unable to get interface by name %v, %v", iFaceName, err)
+		errMsg := fmt.Sprintf("[Azure CNS] Unable to get interface by name %s. Error: %v", iFaceName, err)
 		log.Printf(errMsg)
 		return false, errors.New(errMsg)
 	}
 
+	log.Printf("[Azure CNS] Found interface by name %s", iFaceName)
+
 	return true, nil
 }
 
 // Create creates a network container.
 func (cn *NetworkContainers) Create(createNetworkContainerRequest cns.CreateNetworkContainerRequest) error {
-	log.Printf("[Azure CNS] NetworkContainers.Create called")
+	log.Printf("[Azure CNS] NetworkContainers.Create called for NC: %s", createNetworkContainerRequest.NetworkContainerid)
 	err := createOrUpdateInterface(createNetworkContainerRequest)
-	if err == nil {
-		err = setWeakHostOnInterface(createNetworkContainerRequest.PrimaryInterfaceIdentifier)
-	}
-	log.Printf("[Azure CNS] NetworkContainers.Create finished.")
+	log.Printf("[Azure CNS] NetworkContainers.Create completed for NC: %s with error: %v",
+		createNetworkContainerRequest.NetworkContainerid, err)
+
 	return err
 }
 
 // Update updates a network container.
 func (cn *NetworkContainers) Update(createNetworkContainerRequest cns.CreateNetworkContainerRequest, netpluginConfig *NetPluginConfiguration) error {
-	log.Printf("[Azure CNS] NetworkContainers.Update called")
+	log.Printf("[Azure CNS] NetworkContainers.Update called for NC: %s", createNetworkContainerRequest.NetworkContainerid)
 	err := updateInterface(createNetworkContainerRequest, netpluginConfig)
-	log.Printf("[Azure CNS] NetworkContainers.Update finished.")
+	log.Printf("[Azure CNS] NetworkContainers.Update completed for NC: %s with error: %v",
+		createNetworkContainerRequest.NetworkContainerid, err)
+
 	return err
 }
 
 // Delete deletes a network container.
 func (cn *NetworkContainers) Delete(networkContainerID string) error {
-	log.Printf("[Azure CNS] NetworkContainers.Delete called")
+	log.Printf("[Azure CNS] NetworkContainers.Delete called for NC: %s", networkContainerID)
 	err := deleteInterface(networkContainerID)
-	log.Printf("[Azure CNS] NetworkContainers.Delete finished.")
+	log.Printf("[Azure CNS] NetworkContainers.Delete completed for NC: %s with error: %v", networkContainerID, err)
+
 	return err
 }
 

cns/networkcontainers/networkcontainers_linux.go

@@ -18,7 +18,7 @@ func createOrUpdateInterface(createNetworkContainerRequest cns.CreateNetworkCont
 	return nil
 }
 
-func setWeakHostOnInterface(ipAddress string) error {
+func setWeakHostOnInterface(ipAddress, ncID string) error {
 	return nil
 }
 

cns/networkcontainers/networkcontainers_windows.go

@@ -27,9 +27,7 @@ func createOrUpdateInterface(createNetworkContainerRequest cns.CreateNetworkCont
 		return nil
 	}
 
-	exists, _ := interfaceExists(createNetworkContainerRequest.NetworkContainerid)
-
-	if !exists {
+	if exists, _ := interfaceExists(createNetworkContainerRequest.NetworkContainerid); !exists {
 		return createOrUpdateWithOperation(createNetworkContainerRequest, "CREATE")
 	}
 
@@ -40,7 +38,7 @@ func updateInterface(createNetworkContainerRequest cns.CreateNetworkContainerReq
 	return nil
 }
 
-func setWeakHostOnInterface(ipAddress string) error {
+func setWeakHostOnInterface(ipAddress, ncID string) error {
 	interfaces, err := net.Interfaces()
 	if err != nil {
 		log.Printf("[Azure CNS] Unable to retrieve interfaces on machine. %+v", err)
@@ -76,7 +74,6 @@ func setWeakHostOnInterface(ipAddress string) error {
 	}
 
 	ethIndexString := strconv.Itoa(targetIface.Index)
-	log.Printf("[Azure CNS] Going to setup weak host routing for interface with index[%v, %v]\n", targetIface.Index, ethIndexString)
 
 	args := []string{"/C", "AzureNetworkContainer.exe", "/logpath", log.GetLogDirectory(),
 		"/index",
@@ -88,17 +85,17 @@ func setWeakHostOnInterface(ipAddress string) error {
 		"/weakhostreceive",
 		"true"}
 
-	log.Printf("[Azure CNS] Going to enable weak host send/receive on interface: %v", args)
+	log.Printf("[Azure CNS] Going to enable weak host send/receive on interface: %v for NC: %s", args, ncID)
 	c := exec.Command("cmd", args...)
 
-	loopbackOperationLock.Lock()
 	bytes, err := c.Output()
-	loopbackOperationLock.Unlock()
 
 	if err == nil {
-		log.Printf("[Azure CNS] Successfully updated weak host send/receive on interface %v.\n", string(bytes))
+		log.Printf("[Azure CNS] Successfully updated weak host send/receive for NC: %s on interface %v",
+			ncID, string(bytes))
 	} else {
-		log.Printf("[Azure CNS] Received error while enable weak host send/receive on interface. %v - %v", err.Error(), string(bytes))
+		log.Printf("[Azure CNS] Failed to update weak host send/receive for NC: %s. Error: %v. Output: %v",
+			ncID, err.Error(), string(bytes))
 		return err
 	}
 
@@ -140,17 +137,23 @@ func createOrUpdateWithOperation(createNetworkContainerRequest cns.CreateNetwork
 		"/weakhostreceive",
 		"true"}
 
-	log.Printf("[Azure CNS] Going to create/update network loopback adapter: %v", args)
 	c := exec.Command("cmd", args...)
 
 	loopbackOperationLock.Lock()
+	log.Printf("[Azure CNS] Going to create/update network loopback adapter: %v", args)
 	bytes, err := c.Output()
+	if err == nil {
+		err = setWeakHostOnInterface(createNetworkContainerRequest.PrimaryInterfaceIdentifier,
+			createNetworkContainerRequest.NetworkContainerid)
+	}
 	loopbackOperationLock.Unlock()
 
 	if err == nil {
-		log.Printf("[Azure CNS] Successfully created network loopback adapter %v.\n", string(bytes))
+		log.Printf("[Azure CNS] Successfully created network loopback adapter for NC: %s. Output:%v.",
+			createNetworkContainerRequest.NetworkContainerid, string(bytes))
 	} else {
-		log.Printf("Received error while Creating a Network Container %v %v", err.Error(), string(bytes))
+		log.Printf("Failed to create/update Network Container: %s. Error: %v. Output: %v",
+			createNetworkContainerRequest.NetworkContainerid, err.Error(), string(bytes))
 	}
 
 	return err
@@ -174,17 +177,19 @@ func deleteInterface(networkContainerID string) error {
 		"/operation",
 		"DELETE"}
 
-	log.Printf("[Azure CNS] Going to delete network loopback adapter: %v", args)
 	c := exec.Command("cmd", args...)
 
 	loopbackOperationLock.Lock()
+	log.Printf("[Azure CNS] Going to delete network loopback adapter: %v", args)
 	bytes, err := c.Output()
 	loopbackOperationLock.Unlock()
 
 	if err == nil {
-		log.Printf("[Azure CNS] Successfully deleted network container %v.\n", string(bytes))
+		log.Printf("[Azure CNS] Successfully deleted network container: %s. Output: %v.",
+			networkContainerID, string(bytes))
 	} else {
-		log.Printf("Received error while deleting a Network Container %v %v", err.Error(), string(bytes))
+		log.Printf("Failed to delete Network Container: %s. Error:%v. Output:%v",
+			networkContainerID, err.Error(), string(bytes))
 		return err
 	}
 	return nil