Virtual devices 'missing' in `0.6.x` releases

[rrjjvv]

I'm attempting to get a buildkit-based tool (not directly pertinent to this report)l to work under sysbox. I was contemplating filing an issue for the problem I was facing, but realized I wasn't running the latest version. I upgraded in the hopes of the problem being addressed, but the upgrade (0.5.2 -> 0.6.2) resulted in another problem (this report) much earlier in the startup process, which had worked before. The tool has a startup script which auto-detects/configures MTUs, which stopped working in 0.6.1. The failure manifests slightly different in 0.6.2, so including here as well.

Host system:

$ uname -a
Linux l-9jylpn3 5.19.0-46-generic #47~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Wed Jun 21 15:35:31 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

$ docker version -f json | jq -r '.Server.Version'
24.0.4

Settings-related startup logs (0.5.2, 'working' version):

ul 21 19:43:05 sysbox-fs[1094146]: time="2023-07-21 19:43:05" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
Jul 21 19:43:05 sysbox-fs[1094146]: time="2023-07-21 19:43:05" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
Jul 21 19:43:05 sysbox-fs[1094146]: time="2023-07-21 19:43:05" level=info msg="FUSE dir = /var/lib/sysboxfs"
Jul 21 19:43:05 sysbox-fs[1094146]: time="2023-07-21 19:43:05" level=info msg="IOvec memParser elected"

$ sysbox-mgr --version && sysbox-fs --version && sysbox-runc --version
sysbox-mgr
	edition: 	Community Edition (CE)
	version: 	0.5.2
	commit: 	ea1b7db91031355cb10b850125e0d6502dc38962
	built at: 	Wed May 18 19:49:36 UTC 2022
	built by: 	Rodny Molina
sysbox-fs
	edition: 	Community Edition (CE)
	version: 	0.5.2
	commit: 	95a773a6ea3920f7ab454f1583465c7aea4c701f
	built at: 	Wed May 18 19:49:30 UTC 2022
	built by: 	Rodny Molina
sysbox-runc
	edition: 	Community Edition (CE)
	version: 	0.5.2
	commit: 	d91c42c2125fd7aaf46f66307eb5c2a025f30289
	built at: 	Wed May 18 19:49:04 UTC 2022
	built by: 	Rodny Molina
	oci-specs: 	1.0.2-dev

$ docker run --runtime sysbox-runc --rm -it alpine sh -c 'ls -al /sys/class/net/ && ls -al /sys/devices/virtual/net'
total 0
drwxr-xr-x    2 nobody   nobody           0 Jul 22 01:06 .
drwxr-xr-x   88 nobody   nobody           0 Jul 22 01:06 ..
lrwxrwxrwx    1 root     root             0 Jul 22 01:06 eth0 -> ../../devices/virtual/net/eth0
lrwxrwxrwx    1 root     root             0 Jul 22 01:06 lo -> ../../devices/virtual/net/lo
total 0
drwxr-xr-x   31 nobody   nobody           0 Jul 22 01:06 .
drwxr-xr-x   25 nobody   nobody           0 Jul 22 01:06 ..
drwxr-xr-x    5 root     root             0 Jul 22 01:06 eth0
drwxr-xr-x    5 root     root             0 Jul 22 01:06 lo

Unlike below, the symlink to eth0 is intact, and the routine that auto-configures CNI MTUs works just fine.

Settings-related logs for 0.6.1, the first version with the problem:

Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Shiftfs module found in kernel: yes"
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Shiftfs works properly: no"
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Shiftfs-on-overlayfs works properly: no"
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="ID-mapped mounts supported by kernel: yes"
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Overlayfs on ID-mapped mounts supported by kernel: yes"
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Operating in system container mode."
Jul 21 19:53:15 sysbox-mgr[1096596]: time="2023-07-21 19:53:15" level=info msg="Inner container image preloading enabled."

Jul 21 19:53:15 sysbox-fs[1096618]: time="2023-07-21 19:53:15" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
Jul 21 19:53:15 sysbox-fs[1096618]: time="2023-07-21 19:53:15" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
Jul 21 19:53:15 sysbox-fs[1096618]: time="2023-07-21 19:53:15" level=info msg="FUSE dir = /var/lib/sysboxfs"
Jul 21 19:53:15 sysbox-fs[1096618]: time="2023-07-21 19:53:15" level=info msg="IOvec memParser elected"

$ sysbox-mgr --version && sysbox-fs --version && sysbox-runc --version
sysbox-mgr
	edition: 	Community Edition (CE)
	version: 	0.6.1
	commit: 	ba99c0e7088f1e1ab51f95551f50de9524176655
	built at: 	Sat Apr  8 06:08:57 UTC 2023
	built by: 	Rodny Molina
sysbox-fs
	edition: 	Community Edition (CE)
	version: 	0.6.1
	commit: 	a2631f69c62722c67dfd3aa97a8412b5c4db6a8a
	built at: 	Sat Apr  8 06:08:45 UTC 2023
	built by: 	Rodny Molina
sysbox-runc
	edition: 	Community Edition (CE)
	version: 	0.6.1
	commit: 	278997aab055ad6eec9e48a555b90eef877596b7
	built at: 	Sat Apr  8 06:08:15 UTC 2023
	built by: 	Rodny Molina
	oci-specs: 	1.0.2-dev

$ docker run --runtime sysbox-runc --rm -it alpine sh -c 'ls -al /sys/class/net/ && ls -al /sys/devices/virtual/net'
total 0
drwxr-xr-x    2 nobody   nobody           0 Jul 22 01:08 .
drwxr-xr-x   88 nobody   nobody           0 Jul 22 01:08 ..
lrwxrwxrwx    1 root     root             0 Jul 22 01:08 eth0 -> ../../devices/virtual/net/eth0
lrwxrwxrwx    1 root     root             0 Jul 22 01:08 lo -> ../../devices/virtual/net/lo
total 0
drwxr-xr-x    7 nobody   nobody           0 Jul 20 06:59 br-cfb30d4453e7
drwxr-xr-x    7 nobody   nobody           0 Jul 22 00:28 docker0
drwxr-xr-x    5 nobody   nobody           0 Jul 20 06:59 gpd0
drwxr-xr-x    5 nobody   nobody           0 Jul 20 06:59 lo
drwxr-xr-x    7 nobody   nobody           0 Jul 20 06:59 lxcbr0
drwxr-xr-x    5 nobody   nobody           0 Jul 21 17:26 tun0
drwxr-xr-x    6 nobody   nobody           0 Jul 22 01:08 vethaad19ee

It isn't as obvious without color, but eth0 is a broken symlink; it is not present in the devices hierarchy. This is the ultimate problem (cat: can't open '/sys/class/net/eth0/mtu': No such file or directory). Whether pertinent or not,

1. the number of virtual devices that show up has increased (not a problem for me... just an observation), but not the one I care about
2. owership changed (not a total surprise given the 0.6.1 changelog, but don't know if this a "feature", part of the issue, or irrelevant)
3. the autodetection stuff paints a sad picture, but may be a manifestation of the bug that was fixed in the next release

Logs for 0.6.2 (also not working):

Jul 21 20:08:10 sysbox-fs[1100888]: time="2023-07-21 20:08:10" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
Jul 21 20:08:10 sysbox-fs[1100888]: time="2023-07-21 20:08:10" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
Jul 21 20:08:10 sysbox-fs[1100888]: time="2023-07-21 20:08:10" level=info msg="FUSE dir = /var/lib/sysboxfs"
Jul 21 20:08:10 sysbox-fs[1100888]: time="2023-07-21 20:08:10" level=info msg="IOvec memParser elected"

Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Sysbox data root: /var/lib/sysbox"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Shiftfs module found in kernel: yes"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Shiftfs works properly: yes"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Shiftfs-on-overlayfs works properly: yes"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="ID-mapped mounts supported by kernel: yes"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Overlayfs on ID-mapped mounts supported by kernel: yes"
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Operating in system container mode."
Jul 21 20:08:10 sysbox-mgr[1100864]: time="2023-07-21 20:08:10" level=info msg="Inner container image preloading enabled."

$ sysbox-mgr --version && sysbox-fs --version && sysbox-runc --version
sysbox-mgr
	edition: 	Community Edition (CE)
	version: 	0.6.2
	commit: 	4b5fb1def9abe6a256cfe62bacaf2a7d333d81d2
	built at: 	Mon Jun 12 03:49:55 UTC 2023
	built by: 	Cesar Talledo
sysbox-fs
	edition: 	Community Edition (CE)
	version: 	0.6.2
	commit: 	30fd49edbd51048fed8b2ad0af327598d30b29eb
	built at: 	Mon Jun 12 03:49:46 UTC 2023
	built by: 	Cesar Talledo
sysbox-runc
	edition: 	Community Edition (CE)
	version: 	0.6.2
	commit: 	60ca93c783b19c63581e34aa183421ce0b9b26b7
	built at: 	Mon Jun 12 03:49:19 UTC 2023
	built by: 	Cesar Talledo
	oci-specs: 	1.0.2-dev

$ docker run --runtime sysbox-runc --rm -it alpine sh -c 'ls -al /sys/class/net/ && ls -al /sys/devices/virtual/net/'
total 0
drwxr-xr-x    2 nobody   nobody           0 Jul 22 01:11 .
drwxr-xr-x   88 nobody   nobody           0 Jul 22 01:11 ..
lrwxrwxrwx    1 root     root             0 Jul 22 01:11 eth0 -> ../../devices/virtual/net/eth0
lrwxrwxrwx    1 root     root             0 Jul 22 01:11 lo -> ../../devices/virtual/net/lo
ls: /sys/devices/virtual/net/eth0: No such file or directory
total 0
drwxr-xr-x    5 nobody   nobody           0 Jul 20 06:59 lo

I thought this failure may be of interest due to how it's different than the previous version. First, the 'extra' devices that appeared in 0.6.1 disappeared. And second, even though the symlink is still broken, it actively emits an error, even though it's not directly being referenced.

Other notes:

1. My physical host does not have a real eth0 device (in the off-chance that matters)
2. Another bug report regarding /sys/devices issues suggested disabling shiftfs (--disable-shiftfs) even though the similarity between that issue and this were superficial; I tried it anyway, with no change in results (so I did not explicitly post those results).
3. My original issue was around mounts, so for a time these experiments were run with --allow-immutable-remounts. That flag had no bearing on this issue (so not included), but I undid that change prior to this report to be safe. In other words, everything above is using out-of-the-box settings.

If I've omitted or oversimplified any pertinent information let me know, This seems easy to replicate, but this is fairly new (low-level) territory for me, and I've only been 'seriously' using/investigating this for a couple days now.

[rrjjvv]

A little more info I can contribute. With 0.6.2, I configured sysbox-fs for debug logging. The logs around trying to get info on eth0:

Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: <- Getattr [ID=0x14c Node=0x4 Uid=165536 Gid=165536 Pid=1277611] 0x0 fl=0
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Requested Attr() operation for entry /sys/devices/virtual"
Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: -> [ID=0x14c] Getattr valid=2562047h47m16.854775807s ino=12975295225945701504 size=0 mode=drwxr-xr-x uid=0 gid=0
Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: <- Lookup [ID=0x14e Node=0x4 Uid=165536 Gid=165536 Pid=1277611] "net"
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Requested Lookup() operation for entry net (req ID=0x14e)"
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Executing Lookup() for req-id: 0x14e, handler: SysDevicesVirtual, resource: net"
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Requested Attr() operation for entry /sys/devices/virtual/net"
Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: -> [ID=0x14e] Lookup 0x13 gen=0 valid=2562047h47m16.854775807s attr={valid=2562047h47m16.854775807s ino=18279 size=0 mode=drwxr-xr-x uid=0 gid=0}
Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: <- Lookup [ID=0x150 Node=0x13 Uid=165536 Gid=165536 Pid=1277611] "eth0"
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Requested Lookup() operation for entry eth0 (req ID=0x150)"
Jul 22 12:54:26 sysbox-fs[1277283]: time="2023-07-22 12:54:26" level=debug msg="Executing Lookup() for req-id: 0x150, handler: SysDevicesVirtual, resource: eth0"
Jul 22 12:54:26 sysbox-fs[1277283]: 2023/07/22 12:54:26 FUSE: -> [ID=0x150] Lookup error=ENOENT

While this domain is fairly new to me, poking around code is not. After looking around, the description/comments in nestybox/sysbox-fs@30fd49e looked promising. I created a new sysbox-fs binary (off of master, with that commit reverted) and got better results:

$ docker run --runtime sysbox-runc --rm -it alpine sh -c 'ls -al /sys/class/net/ && ls -al /sys/devices/virtual/net/'
total 0
drwxr-xr-x    2 nobody   nobody           0 Jul 22 20:05 .
drwxr-xr-x   88 nobody   nobody           0 Jul 22 20:05 ..
lrwxrwxrwx    1 root     root             0 Jul 22 20:05 eth0 -> ../../devices/virtual/net/eth0
lrwxrwxrwx    1 root     root             0 Jul 22 20:05 lo -> ../../devices/virtual/net/lo
total 0
drwxr-xr-x    5 nobody   nobody           0 Jul 22 20:05 eth0
drwxr-xr-x    5 nobody   nobody           0 Jul 22 20:05 lo

Corresponding logs:

ul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Requested Attr() operation for entry /sys/devices/virtual"
Jul 22 14:05:37 sysbox-fs[1321602]: 2023/07/22 14:05:37 FUSE: -> [ID=0x14c] Getattr valid=2562047h47m16.854775807s ino=12975295225945701504 size=0 mode=drwxr-xr-x uid=0 gid=0
Jul 22 14:05:37 sysbox-fs[1321602]: 2023/07/22 14:05:37 FUSE: <- Lookup [ID=0x14e Node=0x4 Uid=165536 Gid=165536 Pid=1331614] "net"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Requested Lookup() operation for entry net (req ID=0x14e)"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing Lookup() for req-id: 0x14e, handler: SysDevicesVirtual, resource: net"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing Lookup() for req-id: 0x14e, handler: PassThrough, resource: net"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing nsenterEvent's SendRequest() method"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Received nsenterEvent lookupResponse message."
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Requested Attr() operation for entry /sys/devices/virtual/net"
Jul 22 14:05:37 sysbox-fs[1321602]: 2023/07/22 14:05:37 FUSE: -> [ID=0x14e] Lookup 0x13 gen=0 valid=2562047h47m16.854775807s attr={valid=2562047h47m16.854775807s ino=18279 size=0 mode=drwxr-xr-x uid=65534 gid=65534}
Jul 22 14:05:37 sysbox-fs[1321602]: 2023/07/22 14:05:37 FUSE: <- Lookup [ID=0x150 Node=0x13 Uid=165536 Gid=165536 Pid=1331614] "eth0"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Requested Lookup() operation for entry eth0 (req ID=0x150)"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing Lookup() for req-id: 0x150, handler: SysDevicesVirtual, resource: eth0"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing Lookup() for req-id: 0x150, handler: PassThrough, resource: eth0"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Executing nsenterEvent's SendRequest() method"
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Received nsenterEvent lookupResponse message."
Jul 22 14:05:37 sysbox-fs[1321602]: time="2023-07-22 14:05:37" level=debug msg="Requested Attr() operation for entry /sys/devices/virtual/net/eth0"
Jul 22 14:05:37 sysbox-fs[1321602]: 2023/07/22 14:05:37 FUSE: -> [ID=0x150] Lookup 0x14 gen=0 valid=2562047h47m16.854775807s attr={valid=2562047h47m16.854775807s ino=1998367 size=0 mode=drwxr-xr-x uid=0 gid=0}

I'm guessing that reverting the commit is not an actual fix; it's probably masking a more fundamental issue. Even though eth0 now shows up, the the files under it don't yield any info (e.g., cat /sys/class/net/eth0/mtu does not produce output). These were functional under 0.5.2. Perhaps the file permissions are why? In 0.5.2 they were owned by root (and worked), and in 0.6.x they are owned by nobody; maybe I don't 'permission' to invoke them, despite not showing any obvious error.

Let me know if there's any info you need or if this is of any help.

[rrjjvv]

After digging a little more, it looks like permissions aren't the issue. In the original implementation of the 'virtual' emulation (nestybox/sysbox-fs@ecfc545), all reads were intercepted and given empty responses. After replacing the return value from https://github.com/nestybox/sysbox-fs/blob/30fd49edbd51048fed8b2ad0af327598d30b29eb/handler/implementations/sysDevicesVirtual.go#L129-L137 with

return h.Service.GetPassThroughHandler().Read(n, req)

I can get actual results from that hierarchy.

I would think reads should be considered safe... is this simply a matter of forgetting to implement it? If it should be allowed, my guess is that the preferred implementation would be return n.Read(req.Data), but won't currently work for me for the same reason I needed to revert that other commit (previous comment).

Between these two local hacks, I'm at the same mount issue I started with (that I had hoped would be fixed by upgrading to 0.6.2). If you folks think this current issue can/will be addressed, I'll create a new issue for the mount problem.

[rodnymolina]

@rrjjvv, my apologies for the very late reply. Let me start by thanking you for the detailed description of this issue, you're definitely touching the right code and asking the proper questions, that helps a lot!

I'll need to look at these two commits that you alluded to and find out how can we reconcile "speed" (i.e., this commit), and "functionality" (which requires a revert of that same commit).

[rrjjvv]

my apologies for the very late reply

No worries... I'm just glad that my lengthy/detailed report wasn't the reason!

For what it's worth, I'm not waiting on fixes at this point, for reasons not related to the delay. I ran into this because I had a system where I wanted X to use sysbox, but it didn't have a knob to directly configure the runtime, so I set it at the daemon level. But that resulted in Y not working, which also didn't appear to have a directly configurable runtime, and led to this report. It turns out Y did have an indirect way to configure runtime, so these issues are not hindering me at this time.

That said, I'm still more than happy to provide any additional info you need or to validate any possible fixes. And while I doubt it's not a priority of theirs, I'm sure the folks behind tool Y (the buildkit-based tool I mentioned) wouldn't object to it running properly in scenarios like this.

Also, hats off to this project's logging. For both of the issues in this ticket, I was able to diagnose them with only the logging already present and a view of the source. (Many times I have to add my own ad-hoc logging, or worse, print to console to track down issues.)

[ctalledo]

Hi @rrjjvv, echoing @rodnymolina, thank you very much for the detailed report, much appreciated!

Looks like that commit you identified in sysbox-fs broke things, and the integration test did not catch it (needs better checking).

To provide a bit of context:

• Back in v0.5.*, sysbox did not emulate the contents of /sys/devices/virtual (i.e., when accessing that dir from within a container, Sysbox stayed out of the way, and therefore the access simply showed the contents of the container).

• In v0.6.1, sysbox started to emulate the contents of /sys/devices/virtual, in order to emulate subdirs such as /sys/devices/virtual/dmi. This was needed in order for some apps to run inside sysbox containers in hosts where /sys/devices/virtual/dmi was missing (e.g., Windows WSL, if I recall correctly). However the initial implementation had a bug where the emulation of /sys/devices/virtual would show more devices than it needed to (as you noted above).

• In v0.6.2, we fixed that bug. However, we noticed that the fix was slowing down systemd inside Sysbox containers too much. To overcome that we did a work-around (the last commit in sysbox-fs), but unfortunately it breaks things again :(

Sorry about that; we need to find a way to fix the emulation while keeping systemd inside sysbox fast. Will work on that soon.

[ctalledo]

FYI, PR with the fix is here: nestybox/sysbox-fs#85

[ctalledo]

Issue is fixed, will be present in the next Sysbox release (after v0.6.2, due ~mid September).

Closing.