Portmap plugin is not idempotent if executed in parallel

[aojea]

KIND is running e2e kubernetes jobs in parallel, creating a test environment with high load creating and deleting pods and services constantly. It uses containerd as CRI

It brought my attention that despite the tests are passing there are a considerable number of errors like this (happening in ipv4 and ipv6 jobs, it's independent of the cluster ip family):

Dec 04 10:30:42 kind-worker containerd[79]: time="2019-12-04T10:30:42.632259521Z" level=error msg="StopPodSandbox for \"4474f785df637e833b3c4331e24888ba8d50a34cd798cdd041920e09c52bfa1e\" failed" error="failed to destroy network for sandbox \"4474f785df637e833b3c4331e24888ba8d50a34cd798cdd041920e09c52bfa1e\": could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -X CNI-DN-2cbdc0366bc65971858cc --wait]: exit status 1: iptables: No chain/target/match by that name.\n"

However, my understanding from the portmap plugin code is that this operations should be idempotent and not fail

plugins/plugins/meta/portmap/portmap.go

Line 345 in 6551165

// It should be idempotent - it will not error if the chain does not exist.

After investigating during some time, I think that the problem maybe caused because there are several several teardownsoperations in parallel, don't know if this is the expected behaviour in containerd (cc: @Random-Liu ):

ec 04 10:17:51 kind-worker containerd[79]: time="2019-12-04T10:17:51.066858228Z" level=info msg="StopPodSandbox for \"2f503a1c0253dda279b863a5a53dfc904eee346800a248440cfe625e89e74b30\""
Dec 04 10:17:51 kind-worker containerd[79]: time="2019-12-04T10:17:51.066934330Z" level=info msg="Container to stop \"361103b7742246501e02e71b1b7d08f08ccd2289e6a11216888398efcd337e87\" must be in running or unknown state, current state \"CONTAINER_EXITED\""
Dec 04 10:17:51 kind-worker containerd[79]: time="2019-12-04T10:17:51.067582275Z" level=info msg="StopPodSandbox for \"2f503a1c0253dda279b863a5a53dfc904eee346800a248440cfe625e89e74b30\""
Dec 04 10:17:51 kind-worker containerd[79]: time="2019-12-04T10:17:51.067803063Z" level=info msg="Container to stop \"361103b7742246501e02e71b1b7d08f08ccd2289e6a11216888398efcd337e87\" must be in running or unknown state, current state \"CONTAINER_EXITED\""
...
Dec 04 10:17:51 kind-worker containerd[79]: time="2019-12-04T10:17:51.430655326Z" level=error msg="StopPodSandbox for \"2f503a1c0253dda279b863a5a53dfc904eee346800a248440cfe625e89e74b30\" failed" error="failed to destroy network for sandbox \"2f503a1c0253dda279b863a5a53dfc904eee346800a248440cfe625e89e74b30\": could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -X CNI-DN-a1152567639c8ffbb8b7d --wait]: exit status 1: iptables: No chain/target/match by that name.\n"

It can be possible that there is a race here?

plugins/plugins/meta/portmap/chain.go

Line 69 in 6551165

func (c *chain) teardown(ipt *iptables.IPTables) error {

xref: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-kind-conformance-ipv6/1202166066160078851/artifacts/logs/kind-worker/containerd.log
xref: https://storage.googleapis.com/kubernetes-jenkins/logs/ci-kubernetes-kind-conformance-parallel/1202398984073646081/artifacts/logs/kind-worker/containerd.log

[aojea]

/cc @dcbw

[aojea]

I'm able to reproduce it, the problem is executing several del commands in parallel.
It can be reproduced with cnitool with following parameters:

export CAP_ARGS='{
    "portMappings": [
        {
          "hostPort": 60001,
          "protocol":      "tcp",
          "containerPort": 8080
        }, {
          "hostPort": 60002,
          "protocol":      "tcp",
          "containerPort": 2222
        }
    ]
}'

if we create a namespace called bob and use the KIND cni conflist

If we execute the DEL command sequentially there are no errors:

oot@kind-worker2:~# for i in `seq 1 10`; do /cnitool del kindnet /var/run/netns/bob ; done
root@kind-worker2:~#

However, if we execute the command in parallel:

root@kind-worker2:~# printf %s\\n {0..10} | xargs -n 1 -P 8 /cnitool del kindnet /var/run/netns/bob
could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -X CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: iptables: No chain/target/match by that name.

could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -F CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: iptables: No chain/target/match by that name.

could not teardown ipv6 dnat: running [/usr/sbin/ip6tables -t nat -X CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: ip6tables: No chain/target/match by that name.

could not teardown ipv6 dnat: running [/usr/sbin/ip6tables -t nat -X CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: ip6tables: No chain/target/match by that name.

could not teardown ipv6 dnat: running [/usr/sbin/ip6tables -t nat -X CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: ip6tables: No chain/target/match by that name.

could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -F CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: iptables: No chain/target/match by that name.

could not teardown ipv4 dnat: running [/usr/sbin/iptables -t nat -X CNI-DN-061b764d9409d70dcee31 --wait]: exit status 1: iptables: No chain/target/match by that name.

[aojea]

Should portmap implement some way of modifying the iptables rules atomically?
or some sort of external lock mechanism?
or is that is not supposed to handle scenarios with several parallel executions and this should be fixed in kubernetes/CRI?

[aojea]

ideally I think that we should use iptables-restore like in k8s or add an external locking mechanism like iptables with xtables.lock

[squeed]

ideally I think that we should use iptables-restore like in k8s or add an external locking mechanism like iptables with xtables.lock

Someday it'd be nice to migrate to iptables-restore, but that's a lot of work.

[aojea]

closed by #421