Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Be more agressive acquiring the iptables lock #85771

Merged
merged 1 commit into from Dec 17, 2019

Conversation

aojea
Copy link
Member

@aojea aojea commented Dec 1, 2019

What type of PR is this?

Uncomment only one /kind <> line, hit enter to put that in a new line, and remove leading whitespace from that line:

/kind api-change
/kind bug
/kind cleanup
/kind deprecation
/kind design
/kind documentation
/kind failing-test
/kind feature

/kind flake

What this PR does / why we need it:

if kube-proxy is not able to get the lock it means a maximum penalty of 35 sec, 5 secs waiting to get the lock and 30 secs to retry

2019-11-30T16:47:27.528166227Z stderr F I1130 16:47:27.526891       1 proxier.go:784] Sync failed; retrying in 30s
2019-11-30T16:47:32.576137313Z stderr F E1130 16:47:32.574934       1 proxier.go:792] Failed to ensure that filter chain KUBE-EXTERNAL-SERVICES exists: error creating chain "KUBE-EXTERNAL-SERVICES": exit status 4: Another app is currently holding the xtables lock. Stopped waiting after 5s.

Currently, kubernetes uses the iptables -w 5 option, waiting 5 seconds to acquire the lock

  --wait        -w [seconds]    maximum wait to acquire xtables lock before give up
  --wait-interval -W [usecs]    wait time to try to acquire xtables lock
                                interval to wait for xtables lock
                                default is 1 second

We can be more aggressive trying to acquire the lock using an smaller interval

We can reproduce this situation using flock to hold the lock

acquire the lock in iptables

exec 3> /run/xtables.lock
flock -x 3

observe iptables behaviour with -W = 100000

root@kind-worker:/# ip6tables -L -w 5 -W 100000
Another app is currently holding the xtables lock; still 4s 100000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 100000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 100000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 100000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 100000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock. Stopped waiting after 5s.

observe iptables behaviour with -W = 10000


root@kind-worker:/# ip6tables -L -w 5 -W 10000
Another app is currently holding the xtables lock; still 4s 910000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 810000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 710000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 610000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 510000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 410000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 310000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 210000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 110000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 4s 10000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 910000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 810000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 710000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 610000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 510000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 410000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 310000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 210000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 110000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 3s 10000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 910000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 810000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 710000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 610000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 510000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 410000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 310000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 210000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 110000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 2s 10000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 910000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 810000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 710000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 610000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 510000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 410000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 310000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 210000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 110000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 1s 10000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 910000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 810000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 710000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 610000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 510000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 410000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 310000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 210000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 110000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock; still 0s 10000us time ahead to have a chance to grab the lock...
Another app is currently holding the xtables lock. Stopped waiting after 5s.

remove the lock

exec 3>&-

Which issue(s) this PR fixes:

Fixes #

Special notes for your reviewer:

Seems this was the previous behaviour based on

if err := wait.PollImmediate(200*time.Millisecond, 2*time.Second, func() (bool, error) {

and the one implemented for flushing the chains

const (
// Max time we wait for an iptables flush to complete after we notice it has started
iptablesFlushTimeout = 5 * time.Second
// How often we poll while waiting for an iptables flush to complete
iptablesFlushPollTime = 100 * time.Millisecond
)

Does this PR introduce a user-facing change?:

kubernetes will try to acquire the iptables lock every 100 msec during 5 seconds instead of every second. This specially useful for environments using kube-proxy in iptables mode with a high churn rate of services.

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:


@k8s-ci-robot k8s-ci-robot added release-note Denotes a PR that will be considered when it comes time to generate release notes. kind/flake Categorizes issue or PR as related to a flaky test. size/S Denotes a PR that changes 10-29 lines, ignoring generated files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Dec 1, 2019
pkg/util/iptables/iptables.go Outdated Show resolved Hide resolved
@k8s-ci-robot k8s-ci-robot added sig/network Categorizes an issue or PR as relevant to SIG Network. and removed needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Dec 1, 2019
@aojea
Copy link
Member Author

aojea commented Dec 1, 2019

/test pull-kubernetes-e2e-kind-ipv6
/test pull-kubernetes-conformance-kind-ipv6
/sig network
/assign @thockin @danwinship

@aojea
Copy link
Member Author

aojea commented Dec 1, 2019

/test pull-kubernetes-e2e-kind-ipv6
/test pull-kubernetes-conformance-kind-ipv6

@aojea
Copy link
Member Author

aojea commented Dec 1, 2019

/test pull-kubernetes-e2e-kind-ipv6
/test pull-kubernetes-conformance-kind-ipv6

@danwinship
Copy link
Contributor

in the original PR you noted:

I wasn't able to reproduce the error and I was thinking that this have fixed it, but 🤔 is still happening with this change
#85727 (comment)

Don't know if this make sense now, just let me know if you consider it useful and I'll reopen it

So what changed?

As I said before, I don't think the kind problem is actually a timeout getting the lock, particularly given that kubelet reliably always acquires the lock successfully and kube-proxy reliably hits the timeout. Something else is going on there. (eg like with #82587 where pkg/util/iptables was grabbing the lock itself and then calling the iptable binary which also tried to grab the lock but was guaranteed to fail since we had already grabbed it).

@aojea
Copy link
Member Author

aojea commented Dec 2, 2019

So what changed?

I was investigating more the kind issue #85727 and as you say has to be something different ... However, I could observe that the values used in this PR are similar to the previous values used in kube-proxy when it didn't have the -w option, so I thought that it can make sense to have them again.

Copy link
Member

@thockin thockin left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That looks more palatable to me - @danwinship has the final LGTM

/approve

@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: aojea, thockin

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Dec 3, 2019
@aojea
Copy link
Member Author

aojea commented Dec 3, 2019

/test pull-kubernetes-integration
failed only 1 test that seems unrelated "TestPreemption"
/test pull-kubernetes-e2e-g
failed 6 storage tests that seems unrelated too

@aojea
Copy link
Member Author

aojea commented Dec 3, 2019

/test pull-kubernetes-e2e-gce

iptables has two options to modify the behaviour trying to
acquire the lock.

--wait  -w [seconds]    maximum wait to acquire xtables lock
                        before give up
--wait-interval -W [usecs]  wait time to try to acquire xtables
                            lock
                            interval to wait for xtables lock
                            default is 1 second

Kubernetes uses -w 5 that means that wait 5 seconds to try to
acquire the lock. If we are not able to acquire it, kube-proxy
fails and retries in 30 seconds, that is an important penalty
on sensitive applications.
We can be a bit more aggresive and try to acquire the lock every
100 msec, that means that we have to fail 50 times to not being
able to succeed.
@k8s-ci-robot k8s-ci-robot removed the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Dec 3, 2019
@k8s-ci-robot k8s-ci-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Dec 3, 2019
@aojea
Copy link
Member Author

aojea commented Dec 3, 2019

/test pull-kubernetes-e2e-kind-ipv6
/test pull-kubernetes-conformance-kind-ipv6

@aojea
Copy link
Member Author

aojea commented Dec 3, 2019

/retest

@aojea
Copy link
Member Author

aojea commented Dec 3, 2019

/test pull-kubernetes-e2e-kind-ipv6

@thockin
Copy link
Member

thockin commented Dec 16, 2019

@danwinship this is green - you hold LGTM

@danwinship
Copy link
Contributor

/lgtm

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Dec 17, 2019
@k8s-ci-robot k8s-ci-robot merged commit d0e9018 into kubernetes:master Dec 17, 2019
@k8s-ci-robot k8s-ci-robot added this to the v1.18 milestone Dec 17, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/flake Categorizes issue or PR as related to a flaky test. lgtm "Looks good to me", indicates that a PR is ready to be merged. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. release-note Denotes a PR that will be considered when it comes time to generate release notes. sig/network Categorizes an issue or PR as relevant to SIG Network. size/M Denotes a PR that changes 30-99 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants