mheon
commented
4 years ago Does normal network traffic (not connecting to it via the forwarded port, but e.g. curling a file from within the container) work?
Closed cognition9144 closed 4 years ago
mheon
commented
4 years ago Does normal network traffic (not connecting to it via the forwarded port, but e.g. curling a file from within the container) work?
AkihiroSuda
commented
4 years ago containers-rootlessport seems to die when a connection occurs from the host before the port is created inside the container.
Minimal reproducer:
podman run -it --rm -p 8080:8080 alpine (not nginx:alpine, just plain alpine without httpd).rootlessport-child process is alive.rootlessport-child process is unexpectedly dead.A weird thing is that no debug log is printed during the crash. Also, this is not reproducible with Rootless Docker even though the implementation is almost shared with Podman except the nsenter stuff.
cognition9144
commented
4 years ago Does normal network traffic (not connecting to it via the forwarded port, but e.g. curling a file from within the container) work?
Yes. Inside such a container it can sucessfully curl outside:
bash-4.4$ curl 1.1.1.1
<html>
<head><title>301 Moved Permanently</title></head>
<body bgcolor="white">
<center><h1>301 Moved Permanently</h1></center>
<hr><center>cloudflare-lb</center>
</body>
</html>Another thing to notice, when this problem occurs, network interface cni-podman0 is not presented. But today magically when I recreated the pod, port mapping worked, and later I found there is a network interface called cni-podman0.
mheon
commented
4 years ago Are you certain you're running without root? Can you add --log-level=debug to a podman run command that fails and pastebin the whole output? We should not have any dependencies on CNI when running without root.
giuseppe
commented
4 years ago 
aleks-mariusz
commented
4 years ago Are you certain you're running without root? Can you add
--log-level=debugto apodman runcommand that fails and pastebin the whole output? We should not have any dependencies on CNI when running without root.
I too have this issue.. Here's what my --log-level=debug looks like..
I am trying to work out what might have changed that caused it to get into this state, but am running out of ideas (i've tried reverting every change since it worked). Could really use some help what might have changed, what to check for next?
pi@raspberrypi:~ $ podman ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
8abe143bceb5 docker.io/aleksmariusz/octoprint:1.4.0-20200315 /usr/local/bin/py... 22 minutes ago Up 18 minutes ago 0.0.0.0:8080->80/tcp octoprint14I also checked to make sure the port isn't being bound inside the container..
pi@raspberrypi:~ $ podman exec octoprint14 netstat -tnlp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 0.0.0.0:5000 0.0.0.0:* LISTEN 13/python
tcp 0 0 127.0.0.1:9001 0.0.0.0:* LISTEN 1/python
tcp 0 0 0.0.0.0:80 0.0.0.0:* LISTEN -and that the port inside the container is listening properly..
pi@raspberrypi:~ $ podman exec octoprint14 nc -vz localhost 80
localhost (127.0.0.1:80) openbut outside the container, on the host, the port is not open :-(
pi@raspberrypi:~ $ nc -vz localhost 8080
nc: connect to localhost port 8080 (tcp) failed: Connection refusedAlso i made sure slirp4netns is running (i'm not sure if there's a difference using that, and rootlesskit for port forwarding.. or how to change which implementation i use):
PID USER CPU% MEM% S NI TTY VIRT RES SHR OOM NLWP DISK READ DISK WRITE UTIME+ STIME+ START Command
1 root 0.0 1.7 S 0 ? 14952 4008 2644 0 1 no perm no perm 0:02.95 0:05.31 Jan01 /sbin/init
4093 pi 0.0 0.7 S 0 ? 14928 1652 1408 7 2 0.00 B/s 0.00 B/s 0:00.00 0:00.06 13:07 `- /usr/libexec/podman/conmon --api-version 1 -c 8abe143bceb537673e5d6ccb2fa0548c2b7c7770efd7715cd5ca885b4972e134 -u 8abe143bceb537673e5d6c
4104 pi 0.0 5.6 S 0 ? 15804 12964 4500 55 1 0.00 B/s 0.00 B/s 0:12.54 0:01.39 13:07 | `- /usr/local/bin/python /usr/local/bin/supervisord -c /etc/supervisor/supervisord.conf
4129 pi 6.2 23.3 S 0 ? 70700 54136 5660 233 20 0.00 B/s 0.00 B/s 4:45.24 0:39.58 13:26 | `- /usr/local/bin/python /usr/local/bin/octoprint --iknowwhatimdoing --basedir /data
4128 100100 0.0 1.6 S 0 ? 6140 3788 2772 16 1 0.00 B/s 0.00 B/s 0:00.36 0:00.15 13:26 | `- /usr/sbin/haproxy -db -f /etc/haproxy/haproxy.cfg
4071 pi 0.0 1.1 S 0 pts/1 5780 2524 1596 10 1 0.00 B/s 0.00 B/s 0:00.21 0:00.89 13:26 `- /usr/bin/slirp4netns --disable-host-loopback --mtu 65520 --enable-sandbox -c -e 3 -r 4 --netns-type=path /run/user/1000/netns/cni-f90a8d
747 pi 0.0 0.5 S 0 ? 41232 1064 888 4 1 0.00 B/s 0.00 B/s 0:00.01 0:00.01 11:35 `- podman
354 pi 0.0 1.3 S 0 ? 14512 3108 2204 13 1 0.00 B/s 0.00 B/s 0:00.53 0:00.19 11:34 `- /lib/systemd/systemd --user
369 pi 0.0 1.1 S 0 ? 16420 2492 1032 10 1 no perm no perm 0:00.00 0:00.00 11:34 | `- (sd-pam)I've looked through the difference in debug log-level, but only thing i noticed different is the line is missing when it's not working:
DEBU[0001] Allocated lock 0 for container 96fc8003e676cc1d1e7a6c4f094635448dddbf454679f09cabb2cda0080157bdIs that just a red-herring or does it mean something?
When it's working, querying on the host, shows the expected:
$ sudo ss -tnlp
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 128 127.0.0.1:8125 0.0.0.0:* users:(("netdata",pid=246,fd=26))
LISTEN 0 128 0.0.0.0:19999 0.0.0.0:* users:(("netdata",pid=246,fd=4))
LISTEN 0 128 0.0.0.0:8080 0.0.0.0:* users:(("exe",pid=1016,fd=10))
LISTEN 0 128 0.0.0.0:22 0.0.0.0:* users:(("sshd",pid=277,fd=3))Pid 1016 is:
PID USER CPU% MEM% S NI TTY VIRT RES SHR OOM NLWP DISK READ DISK WRITE UTIME+ STIME+ START Command
1016 pi 0.0 3.7 S 0 pts/0 881M 8472 3496 36 9 0.00 B/s 0.00 B/s 0:00.70 0:00.20 17:36 `- containers-rootlessport
1023 pi 0.0 3.6 S 0 pts/0 873M 8456 3452 36 8 0.00 B/s 0.00 B/s 0:00.59 0:00.23 17:36 | `- containers-rootlessport-childAny ideas on how to debug why containers-rootlessport is not even being ran (when the issue happens)..
AkihiroSuda
commented
4 years ago @aleks-mariusz Could you confirm whether https://github.com/containers/libpod/pull/5552 solves the issue?
cognition9144
commented
4 years ago Are you certain you're running without root? Can you add
--log-level=debugto apodman runcommand that fails and pastebin the whole output? We should not have any dependencies on CNI when running without root.
Yes. I realize that they do not actually corelated. Maybe the if is simply generated by sudo podman run sometime.
Very likely restarting certain images (e.q. calibre-web I refered in the issue) triggers this.
cognition9144
commented
4 years ago @aleks-mariusz Could you confirm whether #5552 solves the issue?
Even after podman system migrate, the problem still exists.
WARN[0010] Failed to add conmon to systemd sandbox cgroup: Unit libpod-conmon-e83572eff474c4b2f54e4ccf71bc20ce949016aa0e65c6c1128cbf636c373005.scope already exists. might indicates the problem
Update: wiredly, if I run with --systemd=false, this warning disappears, but the problem persists.
rhatdan
commented
4 years ago The problem is most likely in iptables and CNI.
aleks-mariusz
commented
4 years ago @aleks-mariusz Could you confirm whether #5552 solves the issue?
tl;dr - didn't seem to? not sure if i tested correctly tho (see details below)
so yesterday evening i saw that 1.8.2 was just released, but dissappointingly it didn't seem to contain this PR merged so it was a bit of a burden to have to (cross-)compile on master (something i'd hope i could put behind me since i found a proper apt source for my distro/arch for podman that is fairly up to date (1.8.2 showed up in the packages). i get that you don't want to include it until confirmed fixed issue but if it passes test would have been good to include it anyway as it sounds like more proper handling of sigpipe.
so i found some time today just now to give this another test, just want to review my testing methodology first:
containers-rootlessport seen running).as the container takes roughly 5 minutes to restart (hey it's a single core <1ghz proc and this is mainly python), the app from step two continues trying to connect even before the service being port-forwarded is available (confirmed with tcpdump and ton of SYN/RST back/forth traffic during container restart)
results? the process containers-rootlessport is not running when the service in the container finishes restarting and the port forwarding does not work.. the tcpdump output seems like a good indication the port forwarding will not bein place when container finishes starting, and confirmed with the missing process
anywya, after (several hours) i (finally) got podman compiled off master and my podman version on the test system is:
pi@raspberrypi:~ $ podman version
Version: 1.8.3-dev
RemoteAPI Version: 1
Go Version: go1.14
Git Commit: d927b43350a079c05f54e984838b851bcc2e5931-dirty
Built: Fri Mar 20 02:36:18 2020
OS/Arch: linux/armHowever, please note: i only swapped in the bin/podman and bin/podman-remote binaries onto my testing system, i am not sure if there's other part i didn't swap in from #5552 ?
aleks-mariusz
commented
4 years ago oh and p.s. if i restart the container and make sure no connection attempts to the forwarded port, the port forwarding does work after the container finishes restarting.. i confirm with tcpdump that no connection attempts are being made.. i'm glad i at least have a work-around i can use to ensure port-forwarding will work..
something about trying to connect to the port forwarded service before it's listening in the container is causing containers-rootlessport to die (so i had hopes that #5552 would have fixed it).
cognition9144
commented
4 years ago Another interesting observation. Pods in a good condition have infrastructure container with empty MountLabel and empty ProcessLabel, whereas infrastructure containers in pods with networking errors are labeled (both of these two types of pods bind-mount some directories).
❯ sdiff good bad
.....
"MountLabel": "", | "MountLabel": "system_u:object_r:container_file_t:s0:
"ProcessLabel": "", | "ProcessLabel": "system_u:system_r:container_t:s0:c18
According
rhatdan
commented
4 years ago The one's without SELinux labels, will run as unconfined. Do you see AVC messages when this happens? grep -i avc /var/log/audit/audit.log
cognition9144
commented
4 years ago Yeah there are flood of AVC messages, although I've set selinux to permissive.
All of them look like this：
type=AVC msg=audit(1584870600.294:1370): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584870900.326:1388): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584871318.497:1409): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584871529.428:1422): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584873600.367:1503): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584873738.695:1515): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584874343.400:1547): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584874948.078:1575): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584875432.620:1598): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1
type=AVC msg=audit(1584876763.478:1661): avc: denied { sendto } for pid=1624 comm="auditd" path=007573657264622D3965626163386339636538363763646233313862626233626531326637663664 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=unix_dgram_socket permissive=1Pretty sure selinux accounts for the problem (unix_dgram_socket). Running a unaccessable pod with generated systemd service automatically makes this pod accessable (due to different CGroup?). The AVCs also disappear.
I don't quite understand why selinux still blocks things in permissive mode. In addition, I have container-selinux-2:2.125.0-1.fc32.noarch.
cognition9144
commented
4 years ago @rhatdan well it's not really related to #5552 AFAIK
rhatdan
commented
4 years ago These AVC's are about the auditd daemon sending packets? Is your container running as auditd_t?
cognition9144
commented
4 years ago These AVC's are about the auditd daemon sending packets? Is your container running as auditd_t?
Well at least I didn't set that argument. But yes all of the unaccessible containers for some reasons have that label. Maybe it's a bug of containers-selinux?
aleks-mariusz
commented
4 years ago May i ask to review whether this issue should have been closed?
As I had mentioned earlier, #5552 did not seem to address this.. i've worked around it by making sure no connections are being made to the container while it's still starting (on my slow system that takes several minutes so is a wide window for a stray connection to cause rootlessport to end up terminating? @xcffl i tried to go back through your notes but see it went off on a selinux tangent (did you mean to imply this issue is related to that), could you comment if #5552 had an effect for you at least?
mheon
commented
4 years ago Hm. If #5552 did not resolve this, I can reopen.
cognition9144
commented
4 years ago @aleks-mariusz well honestly #5552 has no correlation to my issue AFAIK. My issue I think is just because of some random SELinux bugs that container-selinux didn't take care of. Normally I would expect the containers to be labeled but not be blocked. However the observation is only non-labeled containers (which means they are not managed by SELinux) works.
Do you see SELinux complaints as well?
Currently my workaround is to let systemd to manage it. Magically it works. Probably related to different CGroup management to conmon as I addressed in #5605.
github-actions[bot]
commented
4 years ago A friendly reminder that this issue had no activity for 30 days.
rhatdan
commented
4 years ago @mheon @xcffl Has this issue been resolved?
mheon
commented
4 years ago I don't really know - this is AFAIK an issue with rootlesskit. I haven't seen bugs to this effect in a few weeks, which is encouraging, but I was never able to reproduce myself so I can't confirm.
aleks-mariusz
commented
4 years ago FWIW, i am now also unable to reproduce on my original host, today running podman 1.9.0 so either it's been fixed or worked-around.
the test case was basically when podman run -d took enough time (on the order of minutes) before returning to the prompt.. which left enough time for an errant client to try to connect while networking was still being set up... such that any connection attempted prior to returning is what triggered the port to not listen once the container finally did launch
bottom line my raspberry pi is as slow as ever :-) (returning from podman run -d takes well over two minutes, but that's for unrelated reasons (using iscsi and a 100mbps interface hanging off a usb-2 bus), so it's a big enough window), and i can no longer reproduce with 1.9.0 when trying to establish a connection during that time
rhatdan
commented
4 years ago Ok reopen if it happens again.
Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)
/kind bug
Description
Steps to reproduce the issue:
podman run -d -p 7005:8080 quay.io/keycloak/keycloak:latestcurl 127.0.0.1:7005 -vDescribe the results you received: Very often, it gives the following result. Sometimes it's normal before
restartorrmandrunagain.Describe the results you expected:
curlreturns the source code of that pageAdditional information you deem important (e.g. issue happens only occasionally): This issue happens only occasionally. Particularly, it's in favor of the following images:
However, it never touches (probably because it's in
hostmode):Noticably, either
podmanorsudo podmantriggers this issue. After it fails in rootless mode, if you check the same image (could be different container name), it still occurs.However, it doesn't affect other images/containers.
Output of
podman version:Output of
podman info --debug:Package info (e.g. output of
rpm -q podmanorapt list podman):Additional environment details (AWS, VirtualBox, physical, etc.):