compose flake: rootlesskit port forwarder not setup correctly #10052

Luap99 · 2021-04-16T11:48:33Z

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:

podman/pkg/rootlessport/rootlessport_linux.go

Lines 229 to 238 in 4c88035

    
           logrus.Infof("exposing ports %v", cfg.Mappings) 
        
           if err := exposePorts(driver, cfg.Mappings, cfg.ChildIP); err != nil { 
        
           	return err 
        
           } 
        
           // write and close ReadyFD (convention is same as slirp4netns --ready-fd) 
        
           logrus.Info("ready") 
        
           if _, err := readyW.Write([]byte("1")); err != nil { 
        
           	return err 
        
           }

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.

The text was updated successfully, but these errors were encountered:

Luap99 · 2021-04-16T11:51:25Z

@AkihiroSuda PTAL
Somehow the rootless port setup fails but the main podman process thinks it started successfully. Any Ides why it could fail and no error is displayed?

AkihiroSuda · 2021-04-16T12:40:32Z

Is this reproducible manually out of CI? Is this specific to compose?

Luap99 · 2021-04-16T12:48:01Z

I am unable to reproduce locally and I also did no see such issue in other CI tests so it could be specific to compose.

edsantiago · 2021-04-21T13:03:28Z

Hmmmm, it's not only rootless:

compose: simple_port_map - curl (port 5000) failed with status 7

fedora-34beta : compose test on fedora-34beta (root)
- PR podman-remote should show podman.sock info #10080
  - 04-20 16:11
- PR Ensure mount destination is clean, no trailing slash #10069
  - 04-18 12:11
fedora-34beta : compose test on fedora-34beta (rootless)
- PR podman play kube apply correct log driver #10044
- PR Fixes podman-remote save to directories does not work #10025
  - 04-15 07:58
  - 04-15 07:38

compose: port_map_diff_port - curl (port 5001) failed with status 7

fedora-34beta : compose test on fedora-34beta (rootless)
- PR podman play kube apply correct log driver #10044
- PR rmi: don't break when the image is missing a manifest #10033
  - 04-20 15:59

compose: mount_and_label : port 5000

fedora-33 : compose test on fedora-33 (rootless)
- PR [NO TESTS NEEDED] Make an advanced layer diff function private #10056
  - 04-19 09:48
instance:GCEInstance : compose test on fedora-34beta (rootless)
- PR cgroup: do not set cgroup parent when rootless and cgroupfs #9996
  - 04-12 11:12

edsantiago · 2021-05-10T15:49:09Z

This is now our #1 flake. Unfortunately it triggers in many different subtests, so it's hard to just add a skip to ignore the problem.

compose: mount_and_label - curl (port 5000) failed with status 7

fedora-34 : compose test on fedora-34 (rootless)

compose: env_and_volume - down

fedora-34 : compose test on fedora-34 (rootless)
- PR Fix podman-remote build --rm=false ... #10292
  - 05-10 09:37

compose: port_map_diff_port - curl (port 5001) failed with status 7

fedora-34 : compose test on fedora-34 (rootless)
fedora-34beta : compose test on fedora-34beta (rootless)

compose: env_and_volume - curl (port 5000) failed with status 7

fedora-34 : compose test on fedora-34 (root)
- PR fix container startup for empty pidfile #10288
  - 05-10 05:15

compose: env_and_volume : port 5001

fedora-34 : compose test on fedora-34 (root)
- PR fix container startup for empty pidfile #10288
  - 05-10 05:15

Luap99 · 2021-05-12T09:15:32Z

@edsantiago Can you check for network flakes in the system tests, especially the remote tests. I think this is a more general problem, not only compose.

edsantiago · 2021-05-12T16:39:23Z

@Luap99, interesting that you mention it. Here are two flakes from the past week:

sys: podman networking: port on localhost

fedora-34beta : sys podman fedora-34beta root host
- PR Add support for environment variable secrets #10221
  - 05-06 15:19
ubuntu-2010 : sys podman ubuntu-2010 root host
- PR fix incorrect log driver in podman container image #10317
  - 05-12 04:51

The symptom looks similar to my eye. Aside from those two, I don't see any flakes that match. (I do see a new series of iptables flakes, but I'm going to ignore those right now unless they start happening more often).

[EDIT: I just noticed, these are podman, not podman-remote like you asked for]

edsantiago · 2021-05-12T17:33:16Z

Another flake in "port on localhost" test just now: PR #10222, sys podman ubuntu-2104 rootless host (again podman, not remote)

Luap99 · 2021-05-12T20:25:46Z

@edsantiago These are new ones from my PR yesterday, they should be fixed by #10318.

I mean failures like this one https://storage.googleapis.com/cirrus-ci-6707778565701632-fcae48/artifacts/containers/podman/4569209960136704/html/sys-remote-fedora-34-root-host.log.html. The No route to host error message also happens in the rootful compose test. Can you grep for this string in all system test logs? How far can you go back? I want to know if this ever happened before the merge of #9423.

edsantiago · 2021-05-12T20:31:48Z

Unfortunately, no, I have no (sane) way to grep the logs. I just have a very simple script that queries github and cirrus but does not download&preserve the logs for me. I guess I should consider adding that...

edsantiago · 2021-05-24T14:22:19Z

Here's another one outside of compose tests. podman + root, not podman-remote rootless:

sys: podman network reload

fedora-34 : sys podman fedora-34 root host
- PR Bump github.com/containers/storage from 1.31.1 to 1.31.2 #10424
  - 05-21 04:36

edsantiago · 2021-06-02T17:15:56Z

compose: simple_port_map - curl (port 5000) failed with status 7

fedora-34 : compose test on fedora-34 (root)
- PR API one-shot query implementation/handling #10517
  - 06-01 15:08

These too are network-related, one a missing result from a web fetch, another a `ncat: no route to host' error:

sys: podman networking: port on localhost

fedora-34 : sys podman fedora-34 root host
- PR rootless: fix SIGSEGV, Make LISTEN_FDNAMES optional #10481
  - 05-29 06:54

sys: podman pod create - hashtag AllTheOptions

fedora-34 : sys remote fedora-34 root host [remote]
- PR vendor containers/[email protected] #10505
  - 05-31 04:55

edsantiago · 2021-06-03T12:40:45Z

Another Ncat: No route to host:

sys: podman networking: port with --userns=keep-id

fedora-34 : sys podman fedora-34 root host
- PR [v.3.2] events: support disjunctive filters #10534
  - 06-02 11:45

And another compose flake:

compose: mount_and_label - curl (port 5000) failed with status 7

fedora-34 : compose test on fedora-34 (root)
- PR [v.3.2] events: support disjunctive filters #10534
  - 06-02 10:54

vrothberg · 2021-06-23T11:43:20Z

I also see the compose tests flaking frequently.

edsantiago · 2021-07-12T19:38:53Z

Is this where we're tracking Ncat: No route to host flakes? If so, here's some more:

sys: podman networking: port with --userns=keep-id

fedora-34 : sys podman fedora-34 root host
- PR [3.2] vendor containers/[email protected] #10830
  - 07-01 07:23
fedora-34 : sys remote fedora-34 root host [remote]

Luap99 · 2021-07-21T17:16:29Z

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?

The rootlessport forwarder requires a child IP to be set. This must be a valid ip in the container network namespace. The problem is that after a network disconnect and connect the eth0 ip changed. Therefore the packages are dropped since the source ip does no longer exists in the netns. One solution is to set the child IP to 127.0.0.1, however this is a security problem. [1] To fix this we have to recreate the ports after network connect and disconnect. To make this work the rootlessport process exposes a socket where podman network connect/disconnect connect to and send to new child IP to rootlessport. The rootlessport process will remove all ports and recreate them with the new correct child IP. Also bump rootlesskit to v0.14.3 to fix a race with RemovePort(). Fixes containers#10052 [1] https://nvd.nist.gov/vuln/detail/CVE-2021-20199 Signed-off-by: Paul Holzinger <[email protected]>

openshift-ci-robot added the kind/bug Categorizes issue or PR as related to a bug. label Apr 16, 2021

Luap99 added the rootless label Apr 16, 2021

Luap99 mentioned this issue Apr 20, 2021

Ensure mount destination is clean, no trailing slash #10069

Merged

AkihiroSuda added flakes Flakes from Continuous Integration kind/bug Categorizes issue or PR as related to a bug. and removed kind/bug Categorizes issue or PR as related to a bug. rootless labels Apr 21, 2021

Luap99 added the network Networking related issue or feature label Jun 21, 2021

edsantiago mentioned this issue Jul 19, 2021

Flake Fix: Wait before connecting to container port #10982

Merged

Luap99 mentioned this issue Jul 21, 2021

docker-compose: port inaccessibls when using depends on #11004

Closed

rhatdan mentioned this issue Jul 21, 2021

podman build + workdir(?): Error adding network: failed to setup hairpin mode for veth3e067d53: operation not supported #11010

Closed

Luap99 mentioned this issue Aug 2, 2021

fix rootless port forwarding with network dis-/connect #11091

Merged

Luap99 self-assigned this Aug 2, 2021

Luap99 added the In Progress This issue is actively being worked by the assignee, please do not work on this at this time. label Aug 2, 2021

openshift-ci bot closed this as completed in #11091 Aug 3, 2021

edsantiago mentioned this issue Aug 3, 2021

New networking flake (root, compose) #11123

Closed

github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 21, 2023

github-actions bot locked as resolved and limited conversation to collaborators Sep 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

compose flake: rootlesskit port forwarder not setup correctly #10052

compose flake: rootlesskit port forwarder not setup correctly #10052

Luap99 commented Apr 16, 2021

Luap99 commented Apr 16, 2021

AkihiroSuda commented Apr 16, 2021 •

edited

Loading

Luap99 commented Apr 16, 2021

edsantiago commented Apr 21, 2021

edsantiago commented May 10, 2021

Luap99 commented May 12, 2021

edsantiago commented May 12, 2021 •

edited

Loading

edsantiago commented May 12, 2021

Luap99 commented May 12, 2021

edsantiago commented May 12, 2021

edsantiago commented May 24, 2021

edsantiago commented Jun 2, 2021

edsantiago commented Jun 3, 2021

vrothberg commented Jun 23, 2021

edsantiago commented Jul 12, 2021

Luap99 commented Jul 21, 2021

compose flake: rootlesskit port forwarder not setup correctly #10052

compose flake: rootlesskit port forwarder not setup correctly #10052

Comments

Luap99 commented Apr 16, 2021

Luap99 commented Apr 16, 2021

AkihiroSuda commented Apr 16, 2021 • edited Loading

Luap99 commented Apr 16, 2021

edsantiago commented Apr 21, 2021

compose: simple_port_map - curl (port 5000) failed with status 7

compose: port_map_diff_port - curl (port 5001) failed with status 7

compose: mount_and_label : port 5000

edsantiago commented May 10, 2021

compose: mount_and_label - curl (port 5000) failed with status 7

compose: env_and_volume - down

compose: port_map_diff_port - curl (port 5001) failed with status 7

compose: env_and_volume - curl (port 5000) failed with status 7

compose: env_and_volume : port 5001

Luap99 commented May 12, 2021

edsantiago commented May 12, 2021 • edited Loading

sys: podman networking: port on localhost

edsantiago commented May 12, 2021

Luap99 commented May 12, 2021

edsantiago commented May 12, 2021

edsantiago commented May 24, 2021

sys: podman network reload

edsantiago commented Jun 2, 2021

compose: simple_port_map - curl (port 5000) failed with status 7

sys: podman networking: port on localhost

sys: podman pod create - hashtag AllTheOptions

edsantiago commented Jun 3, 2021

sys: podman networking: port with --userns=keep-id

compose: mount_and_label - curl (port 5000) failed with status 7

vrothberg commented Jun 23, 2021

edsantiago commented Jul 12, 2021

sys: podman networking: port with --userns=keep-id

Luap99 commented Jul 21, 2021

AkihiroSuda commented Apr 16, 2021 •

edited

Loading

edsantiago commented May 12, 2021 •

edited

Loading