filter xtables lock warnings when firewalld is active #2135

ctelfer · 2018-04-11T21:33:20Z

It turns out that when running under RHEL 7.3 (and possibly other distributions), Linux can be configured with firewalld, but still run into contention on the xtables lock when performing iptables operations even though use of firewalld doesn't specify the --wait flag for iptables. An example of this as seen in e2e tests is as follows:

Apr 10 15:24:18 tests-BUILD-28-rhel-7-3-dm-ee-test-rhel-0 dockerd[3453]: time="2018-04-10T15:24:18.405670490-04:00" level=debug msg="Firewalld passthrough: ipv4, [-t nat -I DOCKER-INGRESS -p tcp --dport 30017 -j DNAT --to-destination 172.18.0.2:30017]"
Apr 10 15:24:20 tests-BUILD-28-rhel-7-3-dm-ee-test-rhel-0 dockerd[3453]: time="2018-04-10T15:24:20.413670601-04:00" level=error msg="Failed to add ingress: setting up rule failed, [-t nat -I DOCKER-INGRESS -p tcp --dport 30017 -j DNAT --to-destination 172.18.0.2:30017]: Another app is currently holding the xtables lock; waiting (1s) for it to exit...\n (<nil>)"

The first line of the output shows that iptables programming was going through firewalld. The second line consists of output from the iptables command along with the error which is (<nil>). Now, the RawCombinedOutput() function calls Raw() which in turn dispatches between issuing the command either using the Passthrough() function for firewalld execution or the raw() function for direct fork/exec execution. Passthrough() generates the first (debug) line in the output above. Raw() returns both the output from the command and an error value which is non-nil presumably if the command exits with a non-zero exit code indicating failure. The output above therefore indicates that the command exited with a zero-status (successfully) but generated output indicating that it had to wait for 1s to try to acquire the iptables lock.

Now RawCombinedOutput() returns only an error code and it returns an error if either Raw() returns an error OR if the output from iptables is non-empty. This means that the iptables warning above ends up causing RawCombinedOutput() to return an error when in fact none was present. This is not an unknown situation as the code in raw() specifically scans the output that it gets from the iptables operation looking for the xtables lock message. If it sees it, it returns empty output instead. This prevents flagging a false-positive error. However, the firewalld path using the Passthrough() does not perform this filtering and so causes this false-positive error.

One might, at this point, ask whether this is just a spurious log problem or a genuine error given that the operation did, in fact, complete successfully. Unfortunately, the operations that were failing above were due to programming ingress rules using iptables. There were actually a series of iptables modifications that are all needed for correct ingress redirection. If one of the early or middle operations is caught as a failure, libnetwork will not try to program the remaining ones. This leaves the system in an inconsistent state.

This PR consists of two commits. The first simply replicates the output filter from the raw() path on the Passthrough() path and should avoid the error. The second was added based on a suggestion from @fcrisciani and it adds a warning when the xtables lock contention is detected. This makes the fact that the contention is occurring more visible so as to provide better visibility that there may be other issues in this area.

fcrisciani · 2018-04-11T21:47:02Z

iptables/iptables.go

+func filterOutput(output []byte, args ...string) []byte {
+	// ignore iptables' message about xtables lock
+	if strings.Contains(string(output), xLockWaitMsg) {
+		logrus.Warnf("Xtables contention detected during: %s", strings.Join(args, " "))


would be good to still expose the seconds spent waiting for the lock I guess

Are you saying just add "spent up to 1s waiting for lock" to the warning? Or did you want to time it somehow in the code?

I think the suggestion is to dump the original output message as part of the warning i.e. the whole string corresponding to https://git.netfilter.org/iptables/tree/iptables/xshared.c?h=v1.6.0#n261.

codecov-io · 2018-04-11T21:56:19Z

Codecov Report

❗ No coverage uploaded for pull request base (master@b1c7fd5). Click here to learn what that means.
The diff coverage is 40%.

@@           Coverage Diff            @@
##             master   #2135   +/-   ##
========================================
  Coverage          ?   40.6%           
========================================
  Files             ?     139           
  Lines             ?   22457           
  Branches          ?       0           
========================================
  Hits              ?    9119           
  Misses            ?   12002           
  Partials          ?    1336

Impacted Files	Coverage Δ
iptables/iptables.go	`55.7% <40%> (ø)`

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update b1c7fd5...2fb05a3. Read the comment docs.

ddebroy · 2018-04-12T21:43:43Z

@ctelfer it looks like the xLockWaitMsg string being checked against might be changing in latest versions of iptables:

https://git.netfilter.org/iptables/tree/iptables/xshared.c#n307

To handle this for now, perhaps, just match against the prefix Another app is currently holding the xtables lock and skip the ; waiting bit?

We probably need to figure out something to stop depending on the error strings.

ctelfer · 2018-04-13T14:32:08Z

@ddebroy Good catch w.r.t. the changing message. I've added the original output to the warning and have slightly truncated the match string. (which was quite long to being with for something that is being searched using string.Contains())

I'm not convinced that the warning is a good idea, TBH. We may well be in contention all the time in real deployments and just not see it because we've been filtering it. In other words, could be perfectly natural.

W.r.t. how to do this "right": well, flagging any (erm .. most) output from iptables as an error regardless of the operation exit code is hacky in my opinion. I'd be curious as to what conditions the code was trying to catch that a non-zero exit code wouldn't.

fcrisciani · 2018-04-17T15:42:18Z

@ddebroy @ctelfer is this patch ready?

ddebroy

LGTM

fcrisciani · 2018-04-24T22:44:47Z

iptables/iptables.go

+func filterOutput(output []byte, args ...string) []byte {
+	// ignore iptables' message about xtables lock
+	if strings.Contains(string(output), xLockWaitMsg) {
+		logrus.Warnf("xtables contention detected while running [%s]: %q", strings.Join(args, " "), string(output))


I see what you meant regarding the warning, should we follow another approach for the warning, like if the operation takes more than x seconds to execute than we print it?

Hrmm.. Yes, I could see that being a good compromise. Gives us more control over the results in any case. I'll write it up and update.

fcrisciani · 2018-04-25T20:16:38Z

iptables/iptables.go

-	if strings.Contains(string(output), xLockWaitMsg) {
+// Maximum duration that an iptables operation can take
+// before flagging a warning.
+const opWarnTimeMsec = 2000


I would move here the time.Millisecond moltiplication

and also put 2 * time.Second

You're right, that would be cleaner.

fcrisciani · 2018-04-25T20:16:40Z

iptables/iptables.go

+
+func filterOutput(start time.Time, output []byte, args ...string) []byte {
+	// Flag operations that have taken a long time to complete
+	if time.Now().Sub(start) > opWarnTimeMsec*time.Millisecond {


you can use time.Since()

// Since returns the time elapsed since t. // It is shorthand for time.Now().Sub(t). func Since(t Time) Duration { return Now().Sub(t) }

Ah, that's useful. Ok.

This gets filtered for raw iptables calls, but not from calls made through firewalld. The patch just ensures consistency of operation. It also adds a warning when xtables contention detected and truncates the search string slightly as it appears that the suffix will be changing in the near future. Signed-off-by: Chris Telfer <ctelfer@docker.com>

ctelfer · 2018-04-25T20:30:13Z

Addressed comments and squashed the commits.

fcrisciani · 2018-04-25T22:19:18Z

iptables/iptables.go

+func filterOutput(start time.Time, output []byte, args ...string) []byte {
+	// Flag operations that have taken a long time to complete
+	if time.Since(start) > opWarnTime {
+		logrus.Warnf("xtables contention detected while running [%s]: %q", strings.Join(args, " "), string(output))


will merge this one, but maybe would be interesting to print also the time.Since in the log to have an idea of how long it took.

fcrisciani

LGTM

fcrisciani requested a review from ddebroy April 11, 2018 21:45

fcrisciani reviewed Apr 11, 2018

View reviewed changes

ctelfer force-pushed the xtables-filter branch from 2478302 to f099e73 Compare April 13, 2018 14:25

ddebroy approved these changes Apr 17, 2018

View reviewed changes

fcrisciani reviewed Apr 24, 2018

View reviewed changes

fcrisciani reviewed Apr 25, 2018

View reviewed changes

ctelfer force-pushed the xtables-filter branch from 46a6474 to 63b499f Compare April 25, 2018 20:25

ctelfer force-pushed the xtables-filter branch from 63b499f to 2fb05a3 Compare April 25, 2018 20:29

fcrisciani reviewed Apr 25, 2018

View reviewed changes

fcrisciani approved these changes Apr 25, 2018

View reviewed changes

fcrisciani merged commit eee3e06 into moby:master Apr 25, 2018

ctelfer deleted the xtables-filter branch April 26, 2018 14:17

ctelfer mentioned this pull request Apr 26, 2018

Add wait time into xtables lock warning #2142

Merged

thaJeztah mentioned this pull request May 20, 2018

bump libnetwork to eb6b2a57955e5c149d47c3973573216e8f8baa09 moby/moby#37111

Merged

ctelfer mentioned this pull request Jul 3, 2018

17.06 backport iptables output filter #2218

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

filter xtables lock warnings when firewalld is active #2135

filter xtables lock warnings when firewalld is active #2135

ctelfer commented Apr 11, 2018 •

edited by fcrisciani

fcrisciani Apr 11, 2018

ctelfer Apr 12, 2018

ddebroy Apr 12, 2018

codecov-io commented Apr 11, 2018 •

edited

ddebroy commented Apr 12, 2018

ctelfer commented Apr 13, 2018

fcrisciani commented Apr 17, 2018

ddebroy left a comment

fcrisciani Apr 24, 2018

ctelfer Apr 25, 2018

fcrisciani Apr 25, 2018

fcrisciani Apr 25, 2018

ctelfer Apr 25, 2018

fcrisciani Apr 25, 2018

ctelfer Apr 25, 2018

ctelfer commented Apr 25, 2018

fcrisciani Apr 25, 2018

fcrisciani left a comment

filter xtables lock warnings when firewalld is active #2135

filter xtables lock warnings when firewalld is active #2135

Conversation

ctelfer commented Apr 11, 2018 • edited by fcrisciani

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-io commented Apr 11, 2018 • edited

Codecov Report

ddebroy commented Apr 12, 2018

ctelfer commented Apr 13, 2018

fcrisciani commented Apr 17, 2018

ddebroy left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ctelfer commented Apr 25, 2018

Choose a reason for hiding this comment

fcrisciani left a comment

Choose a reason for hiding this comment

ctelfer commented Apr 11, 2018 •

edited by fcrisciani

codecov-io commented Apr 11, 2018 •

edited