podman: compose flake: rootlesskit port forwarder not setup correctly

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description

The rootless compose test flaking regularly in CI. The problem is that the port forwarding with rootlesskit is not working. Rootlesskit does not seem to bind the port on the host. A example test failure with somw debug information can be seen here: https://storage.googleapis.com/cirrus-ci-6707778565701632-fcae48/artifacts/containers/podman/5302424773591040/html/compose-podman-fedora-34beta-rootless-host.log.html Relevant log lines:

time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"starting parent driver\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"opaque=map[builtin.readypipepath:/run/user/30212/libpod/tmp/rootlessport761613945/.bp-ready.pipe builtin.socketpath:/run/user/30212/libpod/tmp/rootlessport761613945/.bp.sock]\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"starting child driver in child netns (\\\"/proc/self/exe\\\" [containers-rootlessport-child])\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"waiting for initComplete\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"initComplete is closed; parent and child established the communication channel\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport: time=\"2021-04-16T04:34:23-05:00\" level=info msg=\"exposing ports [{5000 5000 tcp }]\"\n"
time="2021-04-16T04:34:23-05:00" level=debug msg="rootlessport is ready"

A successful run looks like this:

time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"starting parent driver\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"opaque=map[builtin.readypipepath:/run/user/1000/libpod/tmp/rootlessport734916386/.bp-ready.pipe builtin.socketpath:/run/user/1000/libpod/tmp/rootlessport734916386/.bp.sock]\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"starting child driver in child netns (\\\"/proc/self/exe\\\" [containers-rootlessport-child])\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"waiting for initComplete\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"initComplete is closed; parent and child established the communication channel\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"exposing ports [{5000 5000 tcp }]\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=ready\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport: time=\"2021-04-16T13:33:14+02:00\" level=info msg=\"waiting for exitfd to be closed\"\n"
time="2021-04-16T13:33:14+02:00" level=debug msg="rootlessport is ready"

Relevant code part: https://github.com/containers/podman/blob/4c88035f09474a80264400aa825509900100e32e/pkg/rootlessport/rootlessport_linux.go#L229-L238

We never reach logrus.Info("ready") so the error must be happening inside exposePorts(). However the main podman process never seems to get the error propagated back and thinks rootlesskit started successfully.

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 16 (6 by maintainers)

Commits related to this issue

Most upvoted comments

OK, I found the root cause for the rootless issue. Reproducer:

podman network create testnet
podman run -p 8080:80 --network testnet --name test --replace -d --rm nginx
# this works
curl 127.0.0.1:8080
podman network disconnect testnet test
# this fails as expected with Connection reset by peer (no network is attached)
curl 127.0.0.1:8080
# now connect again to the network
podman network connect testnet test
# curl should work now but it doesn't
# it hangs for some seconds before returning Connection reset by peer
curl 127.0.0.1:8080

docker-compose always runs network disconnect && network connect on the container. I think the race happens between the rootlesskit port setup and docker-compose calling network connect/disconnect at the same time. When rootlesskit was initialized before network connect is finished, port forwarding will be broken.

Rootlesskit port forwarding is broken is because podman sets the child ip for the rootlesskit port forwarder to the eth0 ip address. After disconnect && connect CNI will allocate a new ip. Since the new eth0 ip no longer matches the rootless kit child ip the port forwarding is broken. Ideally we could use 127.0.0.1 as source address but this was changed to fix CVE-2021-20199.

@AkihiroSuda Do you know a good way to fix this? I know rootlesskit offers a way to add/remove ports dynamically, is there way for podman network connect to remove the broken port and add a new port with the correct child ip?