lxc / lxcfs

FUSE filesystem for LXC
https://linuxcontainers.org/lxcfs
Other
1.05k stars 251 forks source link

Intermittent loss of /proc endpoints on snap refresh #582

Closed Vultaire closed 8 months ago

Vultaire commented 1 year ago

Issue description

Snap refreshes of LXD seem to intermittently trigger loss of /proc endpoints. The mounts still exist from the perspective of the containers, but attempting to access them results in messages such as ls: cannot access '/proc/stat': Transport endpoint is not connected.

This seems like it may be somewhat of a corner case, although on a cloud I'm supporting I've see this happen on 2 different hosts within roughly the last month.

The environment in question is running LXD on snap channel 5.0/stable on Ubuntu Focal.

Also, one message seems to jump out of the journalctl logs at me: Error: Error creating database: schema version '43' is more recent than expected '42'. This seems to trigger the LXD service going into a restart loop.

Steps to reproduce

Let snap refresh the LXD snap automatically. (Bug is intermittent and may not readily occur.)

Information to attach

For the most recent occurance which I observed today, I have an NRPE log entry indicating a problem while running an NRPE check:

 Service Warning[2023-01-17 21:36:42] SERVICE ALERT: <redacted>-heat-2;<redacted>-heat-2-corosync_proc;WARNING;SOFT;1;System call sent warnings to stderr: Error: /proc must be mounted

While not completely a smoking gun, as highly circumstantial evidence I have this from journalctl -u snap.lxd.daemon.service:

Jan 17 17:00:45 <redacted> lxd.daemon[3531867]: => LXD is ready
Jan 17 21:35:49 <redacted> systemd[1]: Stopping Service for snap application lxd.daemon...
Jan 17 21:35:49 <redacted> lxd.daemon[732373]: => Stop reason is: snap refresh
Jan 17 21:35:49 <redacted> lxd.daemon[732373]: => Stopping LXD
Jan 17 21:35:49 <redacted> lxd.daemon[3531867]: => LXD exited cleanly
Jan 17 21:35:50 <redacted> lxd.daemon[732373]: ==> Stopped LXD
Jan 17 21:35:50 <redacted> systemd[1]: snap.lxd.daemon.service: Succeeded.
Jan 17 21:35:50 <redacted> systemd[1]: Stopped Service for snap application lxd.daemon.
Jan 17 21:35:54 <redacted> systemd[1]: Started Service for snap application lxd.daemon.
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: => Preparing the system (23541)
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Loading snap configuration
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up mntns symlink (mnt:[4026534411])
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up kmod wrapper
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Preparing /boot
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Preparing a clean copy of /run
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Preparing /run/bin
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Preparing a clean copy of /etc
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Preparing a clean copy of /usr/share/misc
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up ceph configuration
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up LVM configuration
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up OVN configuration
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Rotating logs
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Setting up ZFS (0.8)
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Escaping the systemd cgroups
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ====> Detected cgroup V1
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Escaping the systemd process resource limits
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: ==> Disabling shiftfs on this kernel (auto)
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: => Re-using existing LXCFS
Jan 17 21:35:54 <redacted> lxd.daemon[733180]: => Starting LXD
Jan 17 21:35:54 <redacted> lxd.daemon[733383]: time="2023-01-17T21:35:54Z" level=warning msg=" - Couldn't find the CGroup blkio.weight, disk priority will be ignored"
Jan 17 21:35:54 <redacted> lxd.daemon[733383]: time="2023-01-17T21:35:54Z" level=warning msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"
Jan 17 21:35:54 <redacted> lxd.daemon[733383]: time="2023-01-17T21:35:54Z" level=error msg="Failed to start the daemon" err="Error creating database: schema version '43' is more recent than expec>
Jan 17 21:35:54 <redacted> lxd.daemon[733383]: Error: Error creating database: schema version '43' is more recent than expected '42'
Jan 17 21:35:55 <redacted> lxd.daemon[733180]: => LXD failed to start
Jan 17 21:35:55 <redacted> systemd[1]: snap.lxd.daemon.service: Main process exited, code=exited, status=1/FAILURE
Jan 17 21:35:55 <redacted> systemd[1]: snap.lxd.daemon.service: Failed with result 'exit-code'.

The previous snap refresh occurred at 17:00:37, with its final log message included above. The next refresh, at 21:35, had an error resulting in a restart loop. The timing seems suspiciously close to when the /proc endpoints stopped responding from within the containers.

Required information

stgraber commented 1 year ago

That's a lxcfs crash, moving over to lxcfs.

The schema update thing is caused by snapd potentially having done a rollback for you. LXD can't actually be rolled back because of DB schema changes, you can only ever go forward in releases. Running snap refresh lxd should get you onto the latest revision, taking care of that part.

For the LXCFS crash. We've been adding some debugging logic in the snap to better catch some of those, as well as rolling out a variety of bugfixes with LXD 5.10. The issue with fixing lxcfs issues is that it needs a full restart of LXD (and all containers) to be effective, so it can get a bit tricky to know exactly what version you may be running.

mihalicyn commented 1 year ago

Hi @Vultaire!

Have you got any new reproductions of this issue?

As Stéphane said, we have added some extra debug logic into the LXD snap package and fixed a few issues in the LXCFS.

mihalicyn commented 8 months ago

Let's close for now. Feel free to reopen if issue is still actual and reproducible.