From e7bae9df81f9499b09352161aaaa90ea3dcea19c Mon Sep 17 00:00:00 2001 From: Dan Winship Date: Sat, 19 Feb 2022 11:27:57 -0500 Subject: [PATCH 1/3] Count iptables lines as we write them --- pkg/proxy/iptables/proxier.go | 6 ++---- pkg/proxy/util/utils.go | 20 ++++++++++++++------ pkg/proxy/util/utils_test.go | 5 ++++- 3 files changed, 20 insertions(+), 11 deletions(-) diff --git a/pkg/proxy/iptables/proxier.go b/pkg/proxy/iptables/proxier.go index 0855096c1b1..d0af939db76 100644 --- a/pkg/proxy/iptables/proxier.go +++ b/pkg/proxy/iptables/proxier.go @@ -1507,10 +1507,8 @@ func (proxier *Proxier) syncProxyRules() { "-j", "ACCEPT", ) - numberFilterIptablesRules := utilproxy.CountBytesLines(proxier.filterRules.Bytes()) - metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableFilter)).Set(float64(numberFilterIptablesRules)) - numberNatIptablesRules := utilproxy.CountBytesLines(proxier.natRules.Bytes()) - metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableNAT)).Set(float64(numberNatIptablesRules)) + metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableFilter)).Set(float64(proxier.filterRules.Lines())) + metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableNAT)).Set(float64(proxier.natRules.Lines())) // Write the end-of-table markers. proxier.filterRules.Write("COMMIT") diff --git a/pkg/proxy/util/utils.go b/pkg/proxy/util/utils.go index f20fc194307..1cd78a4a8ca 100644 --- a/pkg/proxy/util/utils.go +++ b/pkg/proxy/util/utils.go @@ -521,7 +521,8 @@ func GetClusterIPByFamily(ipFamily v1.IPFamily, service *v1.Service) string { } type LineBuffer struct { - b bytes.Buffer + b bytes.Buffer + lines int } // Write takes a list of arguments, each a string or []string, joins all the @@ -547,22 +548,34 @@ func (buf *LineBuffer) Write(args ...interface{}) { } } buf.b.WriteByte('\n') + buf.lines++ } // WriteBytes writes bytes to buffer, and terminates with newline. func (buf *LineBuffer) WriteBytes(bytes []byte) { buf.b.Write(bytes) buf.b.WriteByte('\n') + buf.lines++ } +// Reset clears buf func (buf *LineBuffer) Reset() { buf.b.Reset() + buf.lines = 0 } +// Bytes returns the contents of buf as a []byte func (buf *LineBuffer) Bytes() []byte { return buf.b.Bytes() } +// Lines returns the number of lines in buf. Note that more precisely, this returns the +// number of times Write() or WriteBytes() was called; it assumes that you never wrote +// any newlines to the buffer yourself. +func (buf *LineBuffer) Lines() int { + return buf.lines +} + // RevertPorts is closing ports in replacementPortsMap but not in originalPortsMap. In other words, it only // closes the ports opened in this sync. func RevertPorts(replacementPortsMap, originalPortsMap map[netutils.LocalPort]netutils.Closeable) { @@ -574,8 +587,3 @@ func RevertPorts(replacementPortsMap, originalPortsMap map[netutils.LocalPort]ne } } } - -// CountBytesLines counts the number of lines in a bytes slice -func CountBytesLines(b []byte) int { - return bytes.Count(b, []byte{'\n'}) -} diff --git a/pkg/proxy/util/utils_test.go b/pkg/proxy/util/utils_test.go index 4b0c83e1a87..ed5ae7b4d4f 100644 --- a/pkg/proxy/util/utils_test.go +++ b/pkg/proxy/util/utils_test.go @@ -1185,6 +1185,9 @@ func TestLineBufferWrite(t *testing.T) { if want, got := testCase.expected, string(testBuffer.Bytes()); !strings.EqualFold(want, got) { t.Fatalf("write word is %v\n expected: %q, got: %q", testCase.input, want, got) } + if testBuffer.Lines() != 1 { + t.Fatalf("expected 1 line, got: %d", testBuffer.Lines()) + } }) } } @@ -1267,7 +1270,7 @@ func TestWriteCountLines(t *testing.T) { for i := 0; i < testCase.expected; i++ { testBuffer.Write(randSeq()) } - n := CountBytesLines(testBuffer.Bytes()) + n := testBuffer.Lines() if n != testCase.expected { t.Fatalf("lines expected: %d, got: %d", testCase.expected, n) } From f5ad58b57b36599efb7da32e6107068b84efa42f Mon Sep 17 00:00:00 2001 From: Dan Winship Date: Sat, 19 Feb 2022 11:50:53 -0500 Subject: [PATCH 2/3] Only log full iptables-restore input at V(9) In large clusters, the iptables-restore input will be tens of thousands of lines long, and logging it at V(5) essentially means that "kube-proxy -v=5" cannot be used in such clusters to see _other_ things that get logged at V(5), because logs will get rolled over far too quickly. So bump the full-rules logging output down to V(9). --- pkg/proxy/iptables/proxier.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/proxy/iptables/proxier.go b/pkg/proxy/iptables/proxier.go index d0af939db76..ed3e1af53b9 100644 --- a/pkg/proxy/iptables/proxier.go +++ b/pkg/proxy/iptables/proxier.go @@ -1522,7 +1522,7 @@ func (proxier *Proxier) syncProxyRules() { proxier.iptablesData.Write(proxier.natChains.Bytes()) proxier.iptablesData.Write(proxier.natRules.Bytes()) - klog.V(5).InfoS("Restoring iptables", "rules", proxier.iptablesData.Bytes()) + klog.V(9).InfoS("Restoring iptables", "rules", proxier.iptablesData.Bytes()) err = proxier.iptables.RestoreAll(proxier.iptablesData.Bytes(), utiliptables.NoFlushTables, utiliptables.RestoreCounters) if err != nil { if pErr, ok := err.(utiliptables.ParseError); ok { From 9483c272f496dfdd22025ce778f0807aa4f7495e Mon Sep 17 00:00:00 2001 From: Dan Winship Date: Sat, 19 Feb 2022 11:50:53 -0500 Subject: [PATCH 3/3] Log metadata about kube-proxy iptables-restore calls For each iptables-restore call, log the number of services, endpoints, filter chains, filter rules, NAT chains, and NAT rules in the update at V(2), in addition to logging the actual rules if V(9). --- pkg/proxy/iptables/proxier.go | 23 ++++++++++++++--------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/pkg/proxy/iptables/proxier.go b/pkg/proxy/iptables/proxier.go index ed3e1af53b9..757430ae687 100644 --- a/pkg/proxy/iptables/proxier.go +++ b/pkg/proxy/iptables/proxier.go @@ -893,10 +893,6 @@ func (proxier *Proxier) syncProxyRules() { proxier.natChains.Reset() proxier.natRules.Reset() - // Write table headers. - proxier.filterChains.Write("*filter") - proxier.natChains.Write("*nat") - // Make sure we keep stats for the top-level chains, if they existed // (which most should have because we created them above). for _, chainName := range []utiliptables.Chain{kubeServicesChain, kubeExternalServicesChain, kubeForwardChain, kubeNodePortsChain} { @@ -1510,19 +1506,28 @@ func (proxier *Proxier) syncProxyRules() { metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableFilter)).Set(float64(proxier.filterRules.Lines())) metrics.IptablesRulesTotal.WithLabelValues(string(utiliptables.TableNAT)).Set(float64(proxier.natRules.Lines())) - // Write the end-of-table markers. - proxier.filterRules.Write("COMMIT") - proxier.natRules.Write("COMMIT") - // Sync rules. - // NOTE: NoFlushTables is used so we don't flush non-kubernetes chains in the table proxier.iptablesData.Reset() + proxier.iptablesData.WriteString("*filter\n") proxier.iptablesData.Write(proxier.filterChains.Bytes()) proxier.iptablesData.Write(proxier.filterRules.Bytes()) + proxier.iptablesData.WriteString("COMMIT\n") + proxier.iptablesData.WriteString("*nat\n") proxier.iptablesData.Write(proxier.natChains.Bytes()) proxier.iptablesData.Write(proxier.natRules.Bytes()) + proxier.iptablesData.WriteString("COMMIT\n") + klog.V(2).InfoS("Reloading service iptables data", + "numServices", len(proxier.serviceMap), + "numEndpoints", proxier.endpointChainsNumber, + "numFilterChains", proxier.filterChains.Lines(), + "numFilterRules", proxier.filterRules.Lines(), + "numNATChains", proxier.natChains.Lines(), + "numNATRules", proxier.natRules.Lines(), + ) klog.V(9).InfoS("Restoring iptables", "rules", proxier.iptablesData.Bytes()) + + // NOTE: NoFlushTables is used so we don't flush non-kubernetes chains in the table err = proxier.iptables.RestoreAll(proxier.iptablesData.Bytes(), utiliptables.NoFlushTables, utiliptables.RestoreCounters) if err != nil { if pErr, ok := err.(utiliptables.ParseError); ok {