Merge pull request #106847 from cyclinder/log_the_payload

kube-proxy should log the payload when iptables-restore fails

pkg/proxy/iptables/proxier.go

@@ -1515,7 +1515,12 @@ func (proxier *Proxier) syncProxyRules() {
 	klog.V(5).InfoS("Restoring iptables", "rules", proxier.iptablesData.Bytes())
 	err = proxier.iptables.RestoreAll(proxier.iptablesData.Bytes(), utiliptables.NoFlushTables, utiliptables.RestoreCounters)
 	if err != nil {
-		klog.ErrorS(err, "Failed to execute iptables-restore")
+		if pErr, ok := err.(utiliptables.ParseError); ok {
+			lines := utiliptables.ExtractLines(proxier.iptablesData.Bytes(), pErr.Line(), 3)
+			klog.ErrorS(pErr, "Failed to execute iptables-restore", "rules", lines)
+		} else {
+			klog.ErrorS(err, "Failed to execute iptables-restore")
+		}
 		metrics.IptablesRestoreFailuresTotal.Inc()
 		// Revert new local ports.
 		klog.V(2).InfoS("Closing local ports after iptables-restore failure")

pkg/proxy/ipvs/proxier.go

@@ -1607,7 +1607,12 @@ func (proxier *Proxier) syncProxyRules() {
 	klog.V(5).InfoS("Restoring iptables", "rules", string(proxier.iptablesData.Bytes()))
 	err = proxier.iptables.RestoreAll(proxier.iptablesData.Bytes(), utiliptables.NoFlushTables, utiliptables.RestoreCounters)
 	if err != nil {
-		klog.ErrorS(err, "Failed to execute iptables-restore", "rules", string(proxier.iptablesData.Bytes()))
+		if pErr, ok := err.(utiliptables.ParseError); ok {
+			lines := utiliptables.ExtractLines(proxier.iptablesData.Bytes(), pErr.Line(), 3)
+			klog.ErrorS(pErr, "Failed to execute iptables-restore", "rules", lines)
+		} else {
+			klog.ErrorS(err, "Failed to execute iptables-restore", "rules", string(proxier.iptablesData.Bytes()))
+		}
 		metrics.IptablesRestoreFailuresTotal.Inc()
 		// Revert new local ports.
 		utilproxy.RevertPorts(replacementPortsMap, proxier.portsMap)

pkg/util/iptables/iptables.go

@@ -17,10 +17,12 @@ limitations under the License.
 package iptables
 
 import (
+	"bufio"
 	"bytes"
 	"context"
 	"fmt"
 	"regexp"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -423,7 +425,11 @@ func (runner *runner) restoreInternal(args []string, data []byte, flush FlushFla
 	cmd.SetStdin(bytes.NewBuffer(data))
 	b, err := cmd.CombinedOutput()
 	if err != nil {
-		return fmt.Errorf("%v (%s)", err, b)
+		pErr, ok := parseRestoreError(string(b))
+		if ok {
+			return pErr
+		}
+		return fmt.Errorf("%w: %s", err, b)
 	}
 	return nil
 }
@@ -783,3 +789,89 @@ func isResourceError(err error) bool {
 	}
 	return false
 }
+
+// ParseError records the payload when iptables reports an error parsing its input.
+type ParseError interface {
+	// Line returns the line number on which the parse error was reported.
+	// NOTE: First line is 1.
+	Line() int
+	// Error returns the error message of the parse error, including line number.
+	Error() string
+}
+
+type parseError struct {
+	cmd  string
+	line int
+}
+
+func (e parseError) Line() int {
+	return e.line
+}
+
+func (e parseError) Error() string {
+	return fmt.Sprintf("%s: input error on line %d: ", e.cmd, e.line)
+}
+
+// LineData represents a single numbered line of data.
+type LineData struct {
+	// Line holds the line number (the first line is 1).
+	Line int
+	// The data of the line.
+	Data string
+}
+
+var regexpParseError = regexp.MustCompile("line ([1-9][0-9]*) failed$")
+
+// parseRestoreError extracts the line from the error, if it matches returns parseError
+// for example:
+// input: iptables-restore: line 51 failed
+// output: parseError:  cmd = iptables-restore, line = 51
+// NOTE: parseRestoreError depends on the error format of iptables, if it ever changes
+// we need to update this function
+func parseRestoreError(str string) (ParseError, bool) {
+	errors := strings.Split(str, ":")
+	if len(errors) != 2 {
+		return nil, false
+	}
+	cmd := errors[0]
+	matches := regexpParseError.FindStringSubmatch(errors[1])
+	if len(matches) != 2 {
+		return nil, false
+	}
+	line, errMsg := strconv.Atoi(matches[1])
+	if errMsg != nil {
+		return nil, false
+	}
+	return parseError{cmd: cmd, line: line}, true
+}
+
+// ExtractLines extracts the -count and +count data from the lineNum row of lines and return
+// NOTE: lines start from line 1
+func ExtractLines(lines []byte, line, count int) []LineData {
+	// first line is line 1, so line can't be smaller than 1
+	if line < 1 {
+		return nil
+	}
+	start := line - count
+	if start <= 0 {
+		start = 1
+	}
+	end := line + count + 1
+
+	offset := 1
+	scanner := bufio.NewScanner(bytes.NewBuffer(lines))
+	extractLines := make([]LineData, 0, count*2)
+	for scanner.Scan() {
+		if offset >= start && offset < end {
+			extractLines = append(extractLines, LineData{
+				Line: offset,
+				Data: scanner.Text(),
+			})
+		}
+		if offset == end {
+			break
+		}
+		offset++
+	}
+	return extractLines
+}

pkg/util/iptables/iptables_test.go

@@ -1198,3 +1198,63 @@ func TestRestoreAllWaitBackportedIptablesRestore(t *testing.T) {
 		t.Errorf("expected failure")
 	}
 }
+
+// TestExtractLines tests that
+func TestExtractLines(t *testing.T) {
+	mkLines := func(lines ...LineData) []LineData {
+		return lines
+	}
+	lines := "Line1: 1\nLine2: 2\nLine3: 3\nLine4: 4\nLine5: 5\nLine6: 6\nLine7: 7\nLine8: 8\nLine9: 9\nLine10: 10"
+	tests := []struct {
+		count int
+		line  int
+		name  string
+		want  []LineData
+	}{{
+		name:  "test-line-0",
+		count: 3,
+		line:  0,
+		want:  nil,
+	}, {
+		name:  "test-count-0",
+		count: 0,
+		line:  3,
+		want:  mkLines(LineData{3, "Line3: 3"}),
+	}, {
+		name:  "test-common-cases",
+		count: 3,
+		line:  6,
+		want: mkLines(
+			LineData{3, "Line3: 3"},
+			LineData{4, "Line4: 4"},
+			LineData{5, "Line5: 5"},
+			LineData{6, "Line6: 6"},
+			LineData{7, "Line7: 7"},
+			LineData{8, "Line8: 8"},
+			LineData{9, "Line9: 9"}),
+	}, {
+		name:  "test4-bound-cases",
+		count: 11,
+		line:  10,
+		want: mkLines(
+			LineData{1, "Line1: 1"},
+			LineData{2, "Line2: 2"},
+			LineData{3, "Line3: 3"},
+			LineData{4, "Line4: 4"},
+			LineData{5, "Line5: 5"},
+			LineData{6, "Line6: 6"},
+			LineData{7, "Line7: 7"},
+			LineData{8, "Line8: 8"},
+			LineData{9, "Line9: 9"},
+			LineData{10, "Line10: 10"}),
+	}}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got := ExtractLines([]byte(lines), tt.line, tt.count)
+			if !reflect.DeepEqual(got, tt.want) {
+				t.Errorf("got = %v, want = %v", got, tt.want)
+			}
+		})
+	}
+}