Run failure due to iptables xtables lock contention

[rcj4747]

Description

We're seeing contention in a CI environment where the following message is often encountered leading to failures:

Error response from daemon: driver failed programming
external connectivity on endpoint foo
(4ee313e3bf3f375e70c3ee5d00b9000523cb80e5fb29b9ccff565913c74ab6ec):
(iptables failed: iptables -t nat -A POSTROUTING -p tcp -s 172.16.128.7
-d 172.16.128.7 --dport 8081 -j MASQUERADE: Another app is currently
holding the xtables lock. Perhaps you want to use the -w option?

The source of that error message is endpoint.sbJoin in libnetwork/endpoint.go. It calls:

endpoint.sbJoin
driver.ProgramExternalConnectivity (libnetwork/drivers/bridge/bridge.go)
bridgeNetwork.allocatePorts
bridgeNetwork.allocatePortsInternal
bridgeNetwork.allocatePort
PortMapper.MapRange
PortMapper.AppendForwardingTableEntry
PortMapper.Forward
ChainInfo.Forward
iptable.ProgramRule
iptable.Exist
iptable.exists
iptable.existsRaw

iptable.raw calls iptables with --wait if supported, but iptable.existsRaw does not. The invocation of iptables in existsRaw has not changed since 2017 but how OSes behave has.

I've created a simple test to determine if iptables locking behavior has changed when calling iptables -S which is what is invoked in iptable.existsRaw() across several releases of Ubuntu (as we've updated from bionic to focal)

Here is the test file, it takes an exclusive lock and then invokes iptables -S with and without --wait

$ cat flock.test
#!/usr/bin/env bash
set -x

LOCK=/run/xtables.lock

iptables --version
flock --exclusive "${LOCK}" sleep 12 &
sleep 1
time iptables -S
echo Returned: $?
wait
flock --exclusive "${LOCK}" sleep 12 &
sleep 1
time iptables -S -w -W20
echo Returned: $?

We can build images for Ubuntu bionic, focal, and jammy to see how this behaves:

$ cat Dockerfile
ARG IMAGE
FROM $IMAGE

USER root
COPY flock.test /flock.test
RUN apt update
RUN apt install -y iptables
RUN apt clean

CMD /flock.test

$ IMAGE_TAGS=("bionic" "focal" "jammy")
$ for IMAGE_TAG in "${IMAGE_TAGS[@]}"; do
  docker build --quiet -t "flock-test:ubuntu-$IMAGE_TAG" \ 
               --build-arg IMAGE="ubuntu:$IMAGE_TAG" . 
  echo Testing flock-test:ubuntu-"$IMAGE_TAG"
  docker run --cap-add=NET_ADMIN  flock-test:ubuntu-"$IMAGE_TAG"
  echo
done

Ubuntu Bionic Behavior
Summary: iptables waits for the xtables lock without the --wait flag and is successful. Adding --wait is also successful but is noisy as it waits for the lock.

Testing flock-test:ubuntu-bionic
+ LOCK=/run/xtables.lock
+ iptables --version
iptables v1.6.1
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S
Another app is currently holding the xtables lock; still -9s 0us time ahead to have a chance to grab the lock...
-P INPUT ACCEPT
-P FORWARD ACCEPT
-P OUTPUT ACCEPT

real    0m11.012s
user    0m0.004s
sys     0m0.002s
+ echo Returned: 0
+ wait
Returned: 0
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S -w -W20
Another app is currently holding the xtables lock; waiting for it to exit...
Another app is currently holding the xtables lock; waiting for it to exit...
Another app is currently holding the xtables lock; waiting for it to exit...

<Hundreds of lines of this>

Another app is currently holding the xtables lock; waiting for it to exit...
Another app is currently holding the xtables lock; waiting for it to exit...
Another app is currently holding the xtables lock; waiting for it to exit...
-P INPUT ACCEPT
-P FORWARD ACCEPT
-P OUTPUT ACCEPT

real    0m11.012s
user    0m0.120s
sys     0m0.540s
+ echo Returned: 0
Returned: 0

Ubuntu Focal Behavior
Summary: Without the --wait flag the command returns an error immediately, which is what we have observed. Adding --wait makes this successful.

Testing flock-test:ubuntu-focal
+ LOCK=/run/xtables.lock
+ iptables --version
iptables v1.8.4 (legacy)
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S
Another app is currently holding the xtables lock. Perhaps you want to use the -w option?

real    0m0.003s
user    0m0.003s
sys     0m0.000s
Returned: 4
+ echo Returned: 4
+ wait
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S -w -W20
-P INPUT ACCEPT
-P FORWARD ACCEPT
-P OUTPUT ACCEPT

real    0m11.004s
user    0m0.002s
sys     0m0.007s
Returned: 0
+ echo Returned: 0

Ubuntu Jammy Behavior
Summary: Without the --wait flag the call is successful and returns immediately. Adding the --wait performs the same.

Testing flock-test:ubuntu-jammy
+ LOCK=/run/xtables.lock
+ iptables --version
iptables v1.8.7 (nf_tables)
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S
-P INPUT ACCEPT
-P FORWARD ACCEPT
-P OUTPUT ACCEPT

real    0m0.004s
user    0m0.000s
sys     0m0.004s
+ echo Returned: 0
+ wait
Returned: 0
+ sleep 1
+ flock --exclusive /run/xtables.lock sleep 12
+ iptables -S -w -W20
-P INPUT ACCEPT
-P FORWARD ACCEPT
-P OUTPUT ACCEPT

real    0m0.002s
user    0m0.002s
sys     0m0.000s
+ echo Returned: 0
Returned: 0

Reproduce

Concurrent docker runs on Ubuntu Focal can result in failure due to iptables lock contention mapping container ports in the host OS depending on timing.

Expected behavior

Docker should wait for the iptables lock when looking at the exiting rules to avoid this failure.

docker version

Client: Docker Engine - Community
 Version:           20.10.19
 API version:       1.41
 Go version:        go1.18.7
 Git commit:        d85ef84
 Built:             Thu Oct 13 16:46:58 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.19
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.18.7
  Git commit:       c964641
  Built:            Thu Oct 13 16:44:47 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.8
  GitCommit:        9cd3357b7fd7218e4aec3eae239db1f68a5a6ec6
 runc:
  Version:          1.1.4
  GitCommit:        v1.1.4-0-g5fd4c4d
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Docker Buildx (Docker Inc., v0.9.1-docker)
  scan: Docker Scan (Docker Inc., v0.17.0)

Server:
 Containers: 46
  Running: 7
  Paused: 0
  Stopped: 39
 Images: 234
 Server Version: 20.10.19
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 9cd3357b7fd7218e4aec3eae239db1f68a5a6ec6
 runc version: v1.1.4-0-g5fd4c4d
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
  cgroupns
 Kernel Version: 5.15.0-50-generic
 Operating System: Ubuntu 22.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 15.26GiB
 Name: <redacted>
 ID: <redacted>
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Username: <redacted>
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

The docker info is from my machine running Ubuntu Jammy, not CI where we're running Bionic and running into this issue, sorry.