fix: [NPM-LINUX] resiliency for several non-retriable errors

npm/metrics/ai-utils.go

@@ -65,6 +65,7 @@ func SendErrorLogAndMetric(operationID int, format string, args ...interface{})
 		Value:            util.ErrorValue,
 		CustomDimensions: customDimensions,
 	}
+	// SendMetric prints out a log visible in kubectl logs
 	SendMetric(metric)
 
 	// Send error logs

npm/metrics/timer.go

@@ -3,8 +3,8 @@ package metrics
 import (
 	"time"
 
+	"github.com/Azure/azure-container-networking/npm/util"
 	"github.com/prometheus/client_golang/prometheus"
-	"k8s.io/klog"
 )
 
 // Timer is a one-time-use tool for recording time between a start and end point
@@ -27,7 +27,7 @@ func (timer *Timer) stopAndRecord(observer prometheus.Summary) {
 func (timer *Timer) stopAndRecordCRUDExecTime(observer *prometheus.SummaryVec, op OperationKind, hadError bool) {
 	timer.stop()
 	if !op.isValid() {
-		klog.Errorf("Unknown operation [%v] when recording exec time", op)
+		SendErrorLogAndMetric(util.UtilID, "Unknown operation [%v] when recording exec time", op)
 		return
 	}
 	if op != NoOp {

npm/pkg/dataplane/ipsets/ipset.go

@@ -5,8 +5,8 @@ import (
 	"fmt"
 
 	"github.com/Azure/azure-container-networking/log"
+	"github.com/Azure/azure-container-networking/npm/metrics"
 	"github.com/Azure/azure-container-networking/npm/util"
-	"k8s.io/klog"
 )
 
 type IPSetMetadata struct {
@@ -64,10 +64,10 @@ func (setMetadata *IPSetMetadata) GetPrefixName() string {
 	case EmptyHashSet:
 		return fmt.Sprintf("%s%s", util.EmptySetPrefix, setMetadata.Name)
 	case UnknownType: // adding this to appease golint
-		klog.Errorf("experienced unknown type in set metadata: %+v", setMetadata)
+		metrics.SendErrorLogAndMetric(util.UtilID, "experienced unknown type in set metadata: %+v", setMetadata)
 		return Unknown
 	default:
-		klog.Errorf("experienced unexpected type %d in set metadata: %+v", setMetadata.Type, setMetadata)
+		metrics.SendErrorLogAndMetric(util.UtilID, "experienced unexpected type %d in set metadata: %+v", setMetadata.Type, setMetadata)
 		return Unknown
 	}
 }

npm/pkg/dataplane/ipsets/ipsetmanager_linux.go

@@ -50,7 +50,7 @@ const (
 	ipsetIPPortHashString = ipsetIPPortHashFlag
 
 	// creator constants
-	maxTryCount                    = 3
+	maxTryCount                    = 5
 	destroySectionPrefix           = "delete"
 	addOrUpdateSectionPrefix       = "add/update"
 	ipsetRestoreLineFailurePattern = "Error in line (\\d+):"
@@ -201,7 +201,7 @@ func (iMgr *IPSetManager) fileCreatorForFlushAll(ipsetListOutput []byte) (creato
 				Definition: ioutil.AlwaysMatchDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("[RESET-IPSETS] marking flush and upcoming destroy for set %s as a failure due to unknown error", hashedSetName)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "[RESET-IPSETS] marking flush and upcoming destroy for set %s as a failure due to unknown error", hashedSetName)
 					destroyFailureCount++
 					failedNames[hashedSetName] = struct{}{}
 					// TODO mark as a failure
@@ -259,7 +259,7 @@ func (iMgr *IPSetManager) fileCreatorForDestroyAll(names []string, failedNames,
 				Definition: setInUseByKernelDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("[RESET-IPSETS] marking destroy for set %s as a failure since the set is in use by a kernel component", hashedSetName)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "[RESET-IPSETS] marking destroy for set %s as a failure since the set is in use by a kernel component", hashedSetName)
 					failureCountVal++
 					// TODO mark the set as a failure and reconcile what iptables rule or ipset is referring to it
 				},
@@ -275,7 +275,7 @@ func (iMgr *IPSetManager) fileCreatorForDestroyAll(names []string, failedNames,
 				Definition: ioutil.AlwaysMatchDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("[RESET-IPSETS] marking destroy for set %s as a failure due to unknown error", hashedSetName)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "[RESET-IPSETS] marking destroy for set %s as a failure due to unknown error", hashedSetName)
 					failureCountVal++
 					// TODO mark the set as a failure and reconcile what iptables rule or ipset is referring to it
 				},
@@ -539,7 +539,7 @@ func (iMgr *IPSetManager) updateDirtyKernelSets(setsToAddOrUpdate map[string]str
 	if readIndex < len(saveFile) {
 		line, readIndex = parse.Line(readIndex, saveFile)
 		if !hasPrefix(line, createStringWithSpace) {
-			klog.Errorf("expected a create line in ipset save file, but got the following line: %s", string(line))
+			metrics.SendErrorLogAndMetric(util.IpsmID, "expected a create line in ipset save file, but got the following line: %s", string(line))
 			// TODO send error snapshot
 			line, readIndex = nextCreateLine(readIndex, saveFile)
 		}
@@ -595,7 +595,7 @@ func (iMgr *IPSetManager) updateDirtyKernelSets(setsToAddOrUpdate map[string]str
 				break
 			}
 			if !hasPrefix(line, addStringWithSpace) {
-				klog.Errorf("expected an add line, but got the following line: %s", string(line))
+				metrics.SendErrorLogAndMetric(util.IpsmID, "expected an add line, but got the following line: %s", string(line))
 				// TODO send error snapshot
 				line, readIndex = nextCreateLine(readIndex, saveFile)
 				break
@@ -604,7 +604,7 @@ func (iMgr *IPSetManager) updateDirtyKernelSets(setsToAddOrUpdate map[string]str
 			spaceSplitLineAfterAdd := strings.Split(lineAfterAdd, space)
 			parent := spaceSplitLineAfterAdd[0]
 			if len(spaceSplitLineAfterAdd) != 2 || parent != hashedName {
-				klog.Errorf("expected an add line for set %s in ipset save file, but got the following line: %s", hashedName, string(line))
+				metrics.SendErrorLogAndMetric(util.IpsmID, "expected an add line for set %s in ipset save file, but got the following line: %s", hashedName, string(line))
 				// TODO send error snapshot
 				line, readIndex = nextCreateLine(readIndex, saveFile)
 				break
@@ -655,23 +655,23 @@ func haveTypeProblem(set *IPSet, restOfSpaceSplitCreateLine []string) bool {
 	case ipsetSetListString:
 		if set.Kind != ListSet {
 			lineString := fmt.Sprintf("create %s %s", set.HashedName, strings.Join(restOfSpaceSplitCreateLine, " "))
-			klog.Errorf("expected to find a ListSet but have the line: %s", lineString)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "expected to find a ListSet but have the line: %s", lineString)
 			return true
 		}
 	case ipsetNetHashString:
 		if set.Kind != HashSet || set.Type == NamedPorts {
 			lineString := fmt.Sprintf("create %s %s", set.HashedName, strings.Join(restOfSpaceSplitCreateLine, " "))
-			klog.Errorf("expected to find a non-NamedPorts HashSet but have the following line: %s", lineString)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "expected to find a non-NamedPorts HashSet but have the following line: %s", lineString)
 			return true
 		}
 	case ipsetIPPortHashString:
 		if set.Type != NamedPorts {
 			lineString := fmt.Sprintf("create %s %s", set.HashedName, strings.Join(restOfSpaceSplitCreateLine, " "))
-			klog.Errorf("expected to find a NamedPorts set but have the following line: %s", lineString)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "expected to find a NamedPorts set but have the following line: %s", lineString)
 			return true
 		}
 	default:
-		klog.Errorf("unknown type string [%s] in line: %s", typeString, strings.Join(restOfSpaceSplitCreateLine, " "))
+		metrics.SendErrorLogAndMetric(util.IpsmID, "unknown type string [%s] in line: %s", typeString, strings.Join(restOfSpaceSplitCreateLine, " "))
 		return true
 	}
 	return false
@@ -694,7 +694,7 @@ func (iMgr *IPSetManager) flushSetForApply(creator *ioutil.FileCreator, prefixed
 			Definition: ioutil.AlwaysMatchDefinition,
 			Method:     ioutil.ContinueAndAbortSection,
 			Callback: func() {
-				klog.Errorf("skipping flush and upcoming destroy for set %s due to unknown error", prefixedName)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping flush and upcoming destroy for set %s due to unknown error", prefixedName)
 				// TODO mark as a failure
 				// would this ever happen?
 			},
@@ -711,15 +711,15 @@ func (iMgr *IPSetManager) destroySetForApply(creator *ioutil.FileCreator, prefix
 			Definition: setInUseByKernelDefinition,
 			Method:     ioutil.Continue,
 			Callback: func() {
-				klog.Errorf("skipping destroy line for set %s since the set is in use by a kernel component", prefixedName)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping destroy line for set %s since the set is in use by a kernel component", prefixedName)
 				// TODO mark the set as a failure and reconcile what iptables rule or ipset is referring to it
 			},
 		},
 		{
 			Definition: ioutil.AlwaysMatchDefinition,
 			Method:     ioutil.Continue,
 			Callback: func() {
-				klog.Errorf("skipping destroy line for set %s due to unknown error", prefixedName)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping destroy line for set %s due to unknown error", prefixedName)
 			},
 		},
 	}
@@ -747,15 +747,15 @@ func (iMgr *IPSetManager) createSetForApply(creator *ioutil.FileCreator, set *IP
 			Definition: setAlreadyExistsDefinition,
 			Method:     ioutil.ContinueAndAbortSection,
 			Callback: func() {
-				klog.Errorf("skipping create and any following adds/deletes for set %s since the set already exists with different specs", prefixedName)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping create and any following adds/deletes for set %s since the set already exists with different specs", prefixedName)
 				// TODO mark the set as a failure and handle this
 			},
 		},
 		{
 			Definition: ioutil.AlwaysMatchDefinition,
 			Method:     ioutil.ContinueAndAbortSection,
 			Callback: func() {
-				klog.Errorf("skipping create and any following adds/deletes for set %s due to unknown error", prefixedName)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping create and any following adds/deletes for set %s due to unknown error", prefixedName)
 				// TODO same as above error handler
 			},
 		},
@@ -770,7 +770,7 @@ func (iMgr *IPSetManager) deleteMemberForApply(creator *ioutil.FileCreator, set
 			Definition: ioutil.AlwaysMatchDefinition,
 			Method:     ioutil.Continue,
 			Callback: func() {
-				klog.Errorf("skipping delete line for set %s due to unknown error", set.Name)
+				metrics.SendErrorLogAndMetric(util.IpsmID, "skipping delete line for set %s due to unknown error", set.Name)
 			},
 		},
 	}
@@ -785,15 +785,15 @@ func (iMgr *IPSetManager) addMemberForApply(creator *ioutil.FileCreator, set *IP
 				Definition: memberSetDoesntExistDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("skipping add of %s to list %s since the member doesn't exist", member, set.Name)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "skipping add of %s to list %s since the member doesn't exist", member, set.Name)
 					// TODO reconcile
 				},
 			},
 			{
 				Definition: ioutil.AlwaysMatchDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("skipping add of %s to list %s due to unknown error", member, set.Name)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "skipping add of %s to list %s due to unknown error", member, set.Name)
 				},
 			},
 		}
@@ -803,7 +803,7 @@ func (iMgr *IPSetManager) addMemberForApply(creator *ioutil.FileCreator, set *IP
 				Definition: ioutil.AlwaysMatchDefinition,
 				Method:     ioutil.Continue,
 				Callback: func() {
-					klog.Errorf("skipping add line for hash set %s due to unknown error", set.Name)
+					metrics.SendErrorLogAndMetric(util.IpsmID, "skipping add line for hash set %s due to unknown error", set.Name)
 				},
 			},
 		}

npm/pkg/dataplane/ipsets/ipsetmanager_linux_test.go

@@ -489,6 +489,8 @@ func TestDestroyNPMIPSets(t *testing.T) {
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 			},
 			wantErr: true,
 		},
@@ -506,6 +508,8 @@ func TestDestroyNPMIPSets(t *testing.T) {
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+				{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 			},
 			wantErr: true,
 		},
@@ -726,7 +730,9 @@ func TestApplyIPSetsFailureOnSave(t *testing.T) {
 
 func TestApplyIPSetsFailureOnRestore(t *testing.T) {
 	calls := []testutils.TestCmd{
-		// fail 3 times because this is our max try count
+		// fail 5 times because this is our max try count
+		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
@@ -743,7 +749,9 @@ func TestApplyIPSetsFailureOnRestore(t *testing.T) {
 	calls = []testutils.TestCmd{
 		{Cmd: ipsetSaveStringSlice, PipedToCommand: true},
 		{Cmd: []string{"grep", "azure-npm-"}},
-		// fail 3 times because this is our max try count
+		// fail 5 times because this is our max try count
+		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
+		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},
 		{Cmd: ipsetRestoreStringSlice, ExitCode: 1},

npm/pkg/dataplane/policies/chain-management_linux.go

@@ -178,7 +178,9 @@ func (pMgr *PolicyManager) bootup(_ []string) error {
 	if deprecatedErrCode == 0 {
 		klog.Infof("deleted deprecated jump rule from FORWARD chain to AZURE-NPM chain")
 	} else if deprecatedErr != nil {
-		klog.Errorf("failed to delete deprecated jump rule from FORWARD chain to AZURE-NPM chain for unexpected reason with exit code %d and error: %s", deprecatedErrCode, deprecatedErr.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID,
+			"failed to delete deprecated jump rule from FORWARD chain to AZURE-NPM chain for unexpected reason with exit code %d and error: %s",
+			deprecatedErrCode, deprecatedErr.Error())
 	}
 
 	currentChains, err := ioutil.AllCurrentAzureChains(pMgr.ioShim.Exec, util.IptablesDefaultWaitTime)
@@ -437,12 +439,12 @@ func (pMgr *PolicyManager) chainLineNumber(chain string) (int, error) {
 			lineNumberString := string(searchResults[0:firstSpaceIndex])
 			lineNum, err := strconv.Atoi(lineNumberString)
 			if err != nil {
-				return 0, errNoLineNumber
+				return 0, npmerrors.SimpleErrorWrapper(fmt.Sprintf("unable to parse line number. lineNumberString: [%s]. searchResults: [%s]", lineNumberString, string(searchResults)), errNoLineNumber)
 			}
 			return lineNum, nil
 		}
 	}
-	return 0, errUnexpectedLineNumberString
+	return 0, npmerrors.SimpleErrorWrapper(fmt.Sprintf("unable to parse line number. searchResults: [%s]", string(searchResults)), errUnexpectedLineNumberString)
 }
 
 func onMarkSpecs(mark string) []string {

npm/pkg/dataplane/policies/policy_linux.go

@@ -5,9 +5,9 @@ import (
 	"strconv"
 	"strings"
 
+	"github.com/Azure/azure-container-networking/npm/metrics"
 	"github.com/Azure/azure-container-networking/npm/pkg/dataplane/ipsets"
 	"github.com/Azure/azure-container-networking/npm/util"
-	"k8s.io/klog"
 )
 
 type UniqueDirection bool
@@ -117,7 +117,7 @@ func (aclPolicy *ACLPolicy) comment() string {
 	for _, info := range aclPolicy.DstList {
 		if info.IPSet.Type == ipsets.NamedPorts {
 			if foundNamedPortPeer {
-				klog.Errorf("while creating ACL comment, unexpectedly found more than one namedPort peer for ACL:\n%s", aclPolicy.PrettyString())
+				metrics.SendErrorLogAndMetric(util.IptmID, "while creating ACL comment, unexpectedly found more than one namedPort peer for ACL:\n%s", aclPolicy.PrettyString())
 			}
 			namedPortPeer = info
 			foundNamedPortPeer = true

npm/util/ioutil/current-azure-chains.go

@@ -7,9 +7,9 @@ import (
 	"fmt"
 	"strings"
 
+	"github.com/Azure/azure-container-networking/npm/metrics"
 	"github.com/Azure/azure-container-networking/npm/util"
 	npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"
-	"k8s.io/klog"
 	utilexec "k8s.io/utils/exec"
 )
 
@@ -46,14 +46,14 @@ func AllCurrentAzureChains(exec utilexec.Interface, lockWaitTimeSeconds string)
 		// remove the last empty line (since each line ends with a newline)
 		lines = lines[:lastIndex] // this line doesn't impact the array that the slice references
 	} else {
-		klog.Errorf(`while grepping for current Azure chains, expected last line to end in "" but got [%s]. full grep output: [%s]`, lastLine, string(searchResults))
+		metrics.SendErrorLogAndMetric(util.IptmID, `while grepping for current Azure chains, expected last line to end in "" but got [%s]. full grep output: [%s]`, lastLine, string(searchResults))
 	}
 	chainNames := make(map[string]struct{}, len(lines))
 	for _, line := range lines {
 		// line of the form "Chain NAME (1 references)"
 		spaceSeparatedLine := strings.Split(line, " ")
 		if len(spaceSeparatedLine) < minSpacedSectionsForChainLine || len(spaceSeparatedLine[1]) < minAzureChainNameLength {
-			klog.Errorf("while grepping for current Azure chains, got unexpected line [%s] for all current azure chains. full grep output: [%s]", line, string(searchResults))
+			metrics.SendErrorLogAndMetric(util.IptmID, "while grepping for current Azure chains, got unexpected line [%s] for all current azure chains. full grep output: [%s]", line, string(searchResults))
 		} else {
 			chainNames[spaceSeparatedLine[1]] = struct{}{}
 		}