add new telemetry logs for debugging

Author: QxBytes

cni/network/invoker_cns.go

@@ -142,6 +142,8 @@ func (invoker *CNSIPAMInvoker) Add(addConfig IPAMAddConfig) (IPAMAddResult, erro
 		}
 	}
 
+	telemetry.SendEvent(fmt.Sprintf("Received from cns: %+v", response.PodIPInfo))
+
 	addResult := IPAMAddResult{interfaceInfo: make(map[string]network.InterfaceInfo)}
 	numInterfacesWithDefaultRoutes := 0
 

cni/network/multitenancy.go

@@ -267,6 +267,7 @@ func (m *Multitenancy) getNetworkContainersInternal(
 	}
 
 	logger.Info("Network config received from cns", zap.Any("nconfig", ncConfigs))
+	telemetry.SendEvent(fmt.Sprintf("Network config received from cns: %+v", ncConfigs))
 
 	subnetPrefixes := []net.IPNet{}
 	for i := 0; i < len(ncConfigs); i++ {

cni/network/network.go

@@ -326,7 +326,6 @@ func (plugin *NetPlugin) addIpamInvoker(ipamAddConfig IPAMAddConfig) (IPAMAddRes
 	if err != nil {
 		return IPAMAddResult{}, errors.Wrap(err, "failed to add ipam invoker")
 	}
-	telemetry.SendEvent(fmt.Sprintf("Allocated IPAddress from ipam interface: %+v", ipamAddResult.PrettyString()))
 	return ipamAddResult, nil
 }
 
@@ -432,7 +431,7 @@ func (plugin *NetPlugin) Add(args *cniSkel.CmdArgs) error {
 			zap.Any("IPs", cniResult.IPs),
 			zap.Error(log.NewErrorWithoutStackTrace(err)))
 
-		telemetry.SendEvent(fmt.Sprintf("ADD command completed for ipamAddResult verbose: %s epInfos: %s error: %v ", ipamAddResult.PrettyString(), network.FormatStructPointers(epInfos), err))
+		telemetry.SendEvent(fmt.Sprintf("ADD command completed with [ipamAddResult]: %s [epInfos]: %s [error]: %v ", ipamAddResult.PrettyString(), network.FormatStructPointers(epInfos), err))
 	}()
 
 	ipamAddResult = IPAMAddResult{interfaceInfo: make(map[string]network.InterfaceInfo)}
@@ -538,15 +537,9 @@ func (plugin *NetPlugin) Add(args *cniSkel.CmdArgs) error {
 		if err != nil {
 			return fmt.Errorf("IPAM Invoker Add failed with error: %w", err)
 		}
-
-		// TODO: This proably needs to be changed as we return all interfaces...
-		// sendEvent(plugin, fmt.Sprintf("Allocated IPAddress from ipam DefaultInterface: %+v, SecondaryInterfaces: %+v", ipamAddResult.interfaceInfo[ifIndex], ipamAddResult.interfaceInfo))
 	}
 
 	policies := cni.GetPoliciesFromNwCfg(nwCfg.AdditionalArgs)
-	// moved to addIpamInvoker
-	// sendEvent(plugin, fmt.Sprintf("Allocated IPAddress from ipam interface: %+v", ipamAddResult.PrettyString()))
-
 	defer func() { //nolint:gocritic
 		if err != nil {
 			// for swift v1 multi-tenancies scenario, CNI is not supposed to invoke CNS for cleaning Ips
@@ -980,6 +973,7 @@ func (plugin *NetPlugin) Delete(args *cniSkel.CmdArgs) error {
 		logger.Info("DEL command completed",
 			zap.String("pod", k8sPodName),
 			zap.Error(log.NewErrorWithoutStackTrace(err)))
+		telemetry.SendEvent(fmt.Sprintf("DEL command completed: [released ip]: %+v [podname]: %s [namespace]: %s [error]: %v", nwCfg.IPAM.Address, k8sPodName, k8sNamespace, err))
 	}()
 
 	// Parse network configuration from stdin.
@@ -1096,13 +1090,13 @@ func (plugin *NetPlugin) Delete(args *cniSkel.CmdArgs) error {
 	if len(epInfos) == 0 {
 		endpointID := plugin.nm.GetEndpointID(args.ContainerID, args.IfName)
 		if !nwCfg.MultiTenancy {
-			logger.Error("Failed to query endpoint",
+			logger.Warn("Could not query endpoint",
 				zap.String("endpoint", endpointID),
 				zap.Error(err))
 
-			logger.Error("Release ip by ContainerID (endpoint not found)",
+			logger.Warn("Release ip by ContainerID (endpoint not found)",
 				zap.String("containerID", args.ContainerID))
-			telemetry.SendEvent(fmt.Sprintf("Release ip by ContainerID (endpoint not found):%v", args.ContainerID))
+			telemetry.SendEvent(fmt.Sprintf("Release ip by ContainerID (endpoint not found): %s", args.ContainerID))
 			if err = plugin.ipamInvoker.Delete(nil, nwCfg, args, nwInfo.Options); err != nil {
 				return plugin.RetriableError(fmt.Errorf("failed to release address(no endpoint): %w", err))
 			}
@@ -1129,14 +1123,13 @@ func (plugin *NetPlugin) Delete(args *cniSkel.CmdArgs) error {
 	for _, epInfo := range epInfos {
 		logger.Info("Deleting endpoint",
 			zap.String("endpointID", epInfo.EndpointID))
-		telemetry.SendEvent(fmt.Sprintf("Deleting endpoint:%v", epInfo.EndpointID))
 
 		if !nwCfg.MultiTenancy && (epInfo.NICType == cns.InfraNIC || epInfo.NICType == "") {
 			// Delegated/secondary nic ips are statically allocated so we don't need to release
 			// Call into IPAM plugin to release the endpoint's addresses.
 			for i := range epInfo.IPAddresses {
 				logger.Info("Release ip", zap.String("ip", epInfo.IPAddresses[i].IP.String()))
-				telemetry.SendEvent(fmt.Sprintf("Release ip:%s", epInfo.IPAddresses[i].IP.String()))
+				telemetry.SendEvent(fmt.Sprintf("Release ip: %s container id: %s endpoint id: %s", epInfo.IPAddresses[i].IP.String(), args.ContainerID, epInfo.EndpointID))
 				err = plugin.ipamInvoker.Delete(&epInfo.IPAddresses[i], nwCfg, args, nwInfo.Options)
 				if err != nil {
 					return plugin.RetriableError(fmt.Errorf("failed to release address: %w", err))
@@ -1145,6 +1138,7 @@ func (plugin *NetPlugin) Delete(args *cniSkel.CmdArgs) error {
 		} else if epInfo.EnableInfraVnet { // remove in future PR
 			nwCfg.IPAM.Subnet = nwInfo.Subnets[0].Prefix.String()
 			nwCfg.IPAM.Address = epInfo.InfraVnetIP.IP.String()
+			telemetry.SendEvent(fmt.Sprintf("Deleting infra vnet endpoint: container id: %s endpoint id: %s subnet: %s address: %s", args.ContainerID, epInfo.EndpointID, nwCfg.IPAM.Subnet, nwCfg.IPAM.Address))
 			err = plugin.ipamInvoker.Delete(nil, nwCfg, args, nwInfo.Options)
 			if err != nil {
 				return plugin.RetriableError(fmt.Errorf("failed to release address: %w", err))
@@ -1156,7 +1150,6 @@ func (plugin *NetPlugin) Delete(args *cniSkel.CmdArgs) error {
 	if err != nil {
 		return plugin.RetriableError(fmt.Errorf("failed to save state: %w", err))
 	}
-	telemetry.SendEvent(fmt.Sprintf("CNI DEL succeeded : Released ip %+v podname %v namespace %v", nwCfg.IPAM.Address, k8sPodName, k8sNamespace))
 
 	return err
 }

network/endpoint_windows.go

@@ -580,6 +580,7 @@ func (nw *network) deleteEndpointImplHnsV2(ep *endpoint) error {
 	}
 
 	logger.Info("Deleting hcn endpoint with id", zap.String("HnsId", ep.HnsId))
+	telemetry.SendEvent(fmt.Sprintf("Deleting HCN endpoint: %s", ep.HnsId))
 
 	hcnEndpoint, err = Hnsv2.GetEndpointByID(ep.HnsId)
 	if err != nil {

network/manager.go

@@ -5,6 +5,7 @@ package network
 
 import (
 	"context"
+	"fmt"
 	"net"
 	"sync"
 	"time"
@@ -422,10 +423,13 @@ func (nm *networkManager) UpdateEndpointState(eps []*endpoint) error {
 	}
 
 	ifnameToIPInfoMap := generateCNSIPInfoMap(eps) // key : interface name, value : IPInfo
-	for _, ipinfo := range ifnameToIPInfoMap {
-		logger.Info("Update endpoint state", zap.String("hnsEndpointID", ipinfo.HnsEndpointID), zap.String("hnsNetworkID", ipinfo.HnsNetworkID),
+	ifNameToIPInfoCopy := map[string]restserver.IPInfo{}
+	for key, ipinfo := range ifnameToIPInfoMap {
+		logger.Info("Update endpoint state", zap.String("key", key), zap.String("hnsEndpointID", ipinfo.HnsEndpointID), zap.String("hnsNetworkID", ipinfo.HnsNetworkID),
 			zap.String("hostVethName", ipinfo.HostVethName), zap.String("macAddress", ipinfo.MacAddress), zap.String("nicType", string(ipinfo.NICType)))
+		ifNameToIPInfoCopy[key] = *ipinfo
 	}
+	telemetry.SendEvent(fmt.Sprintf("Stateless CNI update endpoint state with: %+v", ifNameToIPInfoCopy))
 
 	// we assume all endpoints have the same container id
 	cnsEndpointID := eps[0].ContainerID

network/network_windows.go

@@ -378,6 +378,7 @@ func (nm *networkManager) newNetworkImplHnsV2(nwInfo *EndpointInfo, extIf *exter
 		// if network not found, create the HNS network.
 		if errors.As(err, &hcn.NetworkNotFoundError{}) {
 			logger.Info("Creating hcn network", zap.Any("hcnNetwork", hcnNetwork))
+			telemetry.SendEvent(fmt.Sprintf("Creating HCN network: %+v", hcnNetwork))
 			hnsResponse, err = Hnsv2.CreateNetwork(hcnNetwork)
 			if err != nil {
 				return nil, fmt.Errorf("Failed to create hcn network: %s due to error: %v", hcnNetwork.Name, err)
@@ -475,6 +476,7 @@ func (nm *networkManager) deleteNetworkImplHnsV2(nw *network) error {
 	var hcnNetwork *hcn.HostComputeNetwork
 	var err error
 	logger.Info("Deleting hcn network with id", zap.String("id", nw.HnsId))
+	telemetry.SendEvent(fmt.Sprintf("Deleting HCN network: %s", nw.HnsId))
 
 	if hcnNetwork, err = Hnsv2.GetNetworkByID(nw.HnsId); err != nil {
 		return fmt.Errorf("Failed to get hcn network with id: %s due to err: %v", nw.HnsId, err)

network/transparent_vlan_endpointclient_linux.go

@@ -144,6 +144,7 @@ func (client *TransparentVlanEndpointClient) ensureCleanPopulateVM() error {
 		if vlanIfErr != nil {
 			// Assume any error is the vlan interface not found
 			logger.Info("vlan interface doesn't exist even though network namespace exists, deleting network namespace...", zap.String("message", vlanIfErr.Error()))
+			telemetry.SendEvent(fmt.Sprintf("vlan interface %s doesn't exist even though network namespace exists, deleting", client.vlanIfName))
 			delErr := client.netnsClient.DeleteNamed(client.vnetNSName)
 			if delErr != nil {
 				return errors.Wrap(delErr, "failed to cleanup/delete ns after noticing vlan veth does not exist")
@@ -155,6 +156,7 @@ func (client *TransparentVlanEndpointClient) ensureCleanPopulateVM() error {
 	if vlanIfInVMErr == nil {
 		// The vlan interface exists in the VM ns because it failed to move into the network ns previously and needs to be cleaned up
 		logger.Info("vlan interface exists on the VM namespace, deleting", zap.String("vlanIfName", client.vlanIfName))
+		telemetry.SendEvent(fmt.Sprintf("vlan interface %s exists on the VM namespace, deleting", client.vlanIfName))
 		if delErr := client.netlink.DeleteLink(client.vlanIfName); delErr != nil {
 			return errors.Wrap(delErr, "failed to clean up vlan interface")
 		}
@@ -300,6 +302,7 @@ func (client *TransparentVlanEndpointClient) PopulateVM(epInfo *EndpointInfo) er
 			return errors.Wrap(deleteNSIfNotNilErr, "failed to move or detect vlan veth inside vnet namespace")
 		}
 		logger.Info("Moving vlan veth into namespace confirmed")
+		telemetry.SendEvent(fmt.Sprintf("Moving vlan veth %s into namespace %s (id: %d) confirmed", client.vlanIfName, client.vnetNSName, client.vnetNSFileDescriptor))
 	} else {
 		logger.Info("Existing NS detected. vlan interface should exist or namespace would've been deleted.", zap.String("vnetNSName", client.vnetNSName), zap.String("vlanIfName", client.vlanIfName))
 	}

telemetry/telemetrybuffer.go

@@ -308,7 +308,7 @@ func (tb *TelemetryBuffer) StartTelemetryService(path string, args []string) err
 	err := tb.plc.KillProcessByName(TelemetryServiceProcessName)
 	if err != nil {
 		if tb.logger != nil {
-			tb.logger.Error("Failed to kill process by", zap.String("TelemetryServiceProcessName", TelemetryServiceProcessName), zap.Error(err))
+			tb.logger.Warn("Failed to kill process by", zap.String("TelemetryServiceProcessName", TelemetryServiceProcessName), zap.Error(err))
 		} else {
 			log.Logf("[Telemetry] Failed to kill process by telemetryServiceProcessName %s due to %v", TelemetryServiceProcessName, err)
 		}