BTRFS Snapshots failing since kernel 6.8.4rc1, still working on 6.8.2 about snapper

[Arnavion]

The reason snapper thinks it should specify qgroups is that /etc/snapper/configs/root contained:

# btrfs qgroup for space aware cleanup algorithms
QGROUP="1/0"

( Code )

I changed this to QGROUP="" and now pre- and post- snapshots work.

[pallaswept]

AHA! I had been wondering what might be unique/unusual in my setup, that I get this problem, and most others don't.... I had a feeling last night it might be the quotas, when I remembered disabling them because after too many snapshots, BTRFS falls on its face with qgroups enabled.

I came here today to ask if anyone else suffering this had qgroups disabled, and here we have the answer. The problem occurs after kernel 6.8.2 when qgroups are disabled in BTRFS config, but not disabled in snapper config.

Great work, kudos and mega thanks, @Arnavion !

I disabled space-aware cleanups by changing the snapper config as per the above, snapshots still give me the error 2 messages, but they appear to be successfully created:

2024-04-15 12:14:08 MIL libsnapper(300) snapperd.cc(main):283 - Requesting DBus name
2024-04-15 12:14:08 MIL libsnapper(300) snapperd.cc(main):298 - Loading snapper configs
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(getConfigs):355 - Snapper get-configs
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(getConfigs):356 - libsnapper version 0.10.7
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(reload):922 - loading file /etc/sysconfig/snapper
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:SNAPPER_CONFIGS value:root home
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/root
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/home
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/home
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:ALLOW_USERS value:
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:ALLOW_GROUPS value:
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:ALLOW_USERS value:
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:ALLOW_GROUPS value:
2024-04-15 12:14:08 MIL libsnapper(300) snapperd.cc(main):311 - Listening for method calls and signals
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(Snapper):97 - Snapper constructor
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(Snapper):98 - snapper version 0.10.7
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(Snapper):99 - libsnapper version 7.4.0
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(Snapper):100 - config_name:root root_prefix:/ disable_filters:false
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/root
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:FSTYPE value:btrfs
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:QGROUP value:
2024-04-15 12:14:08 MIL libsnapper(300) Selinux.cc(_is_selinux_enabled):141 - SELinux support disabled
2024-04-15 12:14:08 MIL libsnapper(300) AsciiFile.cc(get_value):1078 - key:SYNC_ACL value:no
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(Snapper):130 - subvolume:/ filesystem:btrfs
2024-04-15 12:14:08 MIL libsnapper(300) Snapper.cc(loadIgnorePatterns):204 - number of ignore patterns:8
2024-04-15 12:14:08 MIL libsnapper(300) Snapshot.cc(read):344 - found 98 snapshots
2024-04-15 12:14:08 WAR libsnapper(300) FileUtils.cc(SDir):88 - THROW: open failed path://.snapshots/9980 errno:2 (No such file or directory)
2024-04-15 12:14:08 WAR libsnapper(300) Btrfs.cc(checkSnapshot):490 - CAUGHT: open failed path://.snapshots/9980 errno:2 (No such file or directory)
2024-04-15 12:14:08 MIL libsnapper(300) SystemCmd.cc(SystemCmd):48 - constructor SystemCmd: /usr/lib/snapper/plugins/grub --refresh
2024-04-15 12:14:09 MIL libsnapper(300) SystemCmd.cc(execute):180 - stopwatch 1.472239s for "/usr/lib/snapper/plugins/grub --refresh"
2024-04-15 12:14:09 MIL libsnapper(300) SystemCmd.cc(execute):194 - system() Returns:0
2024-04-15 12:14:14 WAR libsnapper(300) Snapper.cc(calculateUsedSpace):928 - THROW: quota rescan or sync failed
2024-04-15 12:14:14 WAR libsnapper(300) Client.cc(dispatch):2049 - CAUGHT: quota rescan or sync failed
2024-04-15 12:14:44 MIL libsnapper(300) Snapper.cc(~Snapper):142 - Snapper destructor
2024-04-15 12:15:14 MIL libsnapper(300) snapperd.cc(main):315 - Exiting

> sudo snapper list
....
9980  | single |       | Mon Apr 15 12:14:08 2024 | root | timeline |                                           |              

I notice that my logs from the time running on kernel 6.8.2, also have this error 2 in them, in spite of working snapshots.

I feel like perhaps we can resolve these cases now, that's fine from my perspective - my system and documentation are updated with this new step in the process to disable qgroups, and my snapshots are working... but I do wonder - is this the intended behaviour from snapper? If everyone has to update all their docs on disabling BTRFS qgroups, like I did, that's a lot of hours. Perhaps there's some way for snapper to fail gracefully when there's no match between the config file and the filesystem. And we do have these error 2 messages, which appear to be mostly cosmetic, but, are they intended? While they do no harm they are informative, but a little unsightly. I really don't know.

Should I leave this issue open, in case somebody wants to track changes to snapper? I don't know enough to make a call here, so just let me know what you want me to do :)

[Arnavion]

Yes, the incorrect Found # snapshots and open failed path://.snapshots/# ENOENT errors still happen even when the snapshots succeed. I don't know if it's an off-by-one bug or not, but either way it doesn't seem to create a problem.

re: the snapper config, I'm not sure how it got into the situation that / did not have quotas enabled but snapper config had QGROUPS="1/0". This install is from 2019 and I don't think I disabled quotas manually. The /etc/snapper/configs/root itself is from 2021. I checked another PC that was installed in 2022 and that one does have quotas enabled. So possibly sometime between 2019 and 2021 the default of new installs changed to enable quotas, and then in 2021 something created /etc/snapper/configs/root with the assumption that all installs have quotas enabled, and it went unnoticed until kernel 6.8.4

Or maybe I really did disable quotas for some reason back in 2019 and just don't remember.

[Arnavion]

Weird that it was all cool until 6.8.4, I'm sure one of you who know snapper/BTRFS better than I, will be able to make sense of that.

It's probably because of what I wrote in #894 (comment) . The validation of specifying qgroup options for non-existent qgroup is new in kernel 6.8.4

[aschnell]

Thanks everybody helping to debug this problem. I will see that snapper handles the situation better since suddenly having no new snapshots is really bad.

[alpolunin]

Thanks! I had the same problem.

[aschnell]

Snapshots work fine for me with kernel 6.8.4-rc1-1-default.

The logs show that the ioctl to create a snapshot fails. How that can be affected by the cleanup algorithm is totally unclear to me.

[pallaswept]

Thanks for looking at it for me @aschnell

I figured it must be working for most people, or there'd be a big noise about it.

I thought it looked like it failed at the point of creating a btrfs subvol, and yet, it will create one manually, so... Yeh, it's weird.

Perhaps there's some other way I'm influencing this, by my rebooting, and selecting the older kernel in GRUB? (BTW I checked, the command lines are the same) I mean, obviously it's not only the kernel that is the issue here... but I've not the first idea where to look next.

[exincore]

I seem to have been affected by this since I installed a week ago (snapper list shows no zypp or timeline snapshots). However, automatic timeline snapshots have been working for my /home directory, without any configuration change other than sudo snapper -c home create-config /home/.

[Arnavion]

As another user mentioned in https://bugzilla.opensuse.org/show_bug.cgi?id=1222674 , snapper-zypp-plugin is also not automatically creating pre- and post- snapshots.

/var/log/zypper.log says:

2024-04-14 15:43:23 <2> futaba(2367565) [PLUGIN] PluginScript.cc(~PluginDumpStderr):86 ! MIL creating pre snapshot
2024-04-14 15:43:23 <2> futaba(2367565) [PLUGIN] PluginScript.cc(~PluginDumpStderr):86 ! WAR THROW: dbus error exception
2024-04-14 15:43:23 <2> futaba(2367565) [PLUGIN] PluginScript.cc(~PluginDumpStderr):86 ! WAR CAUGHT: dbus error exception
2024-04-14 15:43:23 <2> futaba(2367565) [PLUGIN] PluginScript.cc(~PluginDumpStderr):86 ! ERR Creating snapshot failed.

... which lines up with busctl --system monitor org.opensuse.snapper saying:

‣ Type=error  Endian=l  Flags=1  Version=1 Cookie=5  ReplyCookie=2  Timestamp="Sun 2024-04-14 22:43:23.544691 UTC"
  Sender=:1.1199  Destination=:1.1198
  ErrorName=error.create_snapshot_failed  ErrorMessage="org.freedesktop.DBus.Error.Failed"
  UniqueName=:1.1199
  MESSAGE "s" {
          STRING "org.freedesktop.DBus.Error.Failed";
  };

So I changed snapperd.service to strace it:

ExecStart=strace -f -- /usr/sbin/snapperd

... and then the service log says:

Apr 14 15:43:23 futaba strace[2367821]: [pid 2367825] openat(AT_FDCWD, "/", O_RDONLY|O_NOATIME|O_CLOEXEC) = 6
Apr 14 15:43:23 futaba strace[2367821]: [pid 2367825] openat(AT_FDCWD, "/", O_RDONLY|O_NOATIME|O_CLOEXEC) = 7
Apr 14 15:43:23 futaba strace[2367821]: [pid 2367825] ioctl(7, BTRFS_IOC_SNAP_CREATE_V2, {fd=6, flags=BTRFS_SUBVOL_RDONLY|BTRFS_SUBVOL_QGROUP_INHERIT, size=80, qgroup_inherit={flags=0, num_qgroups=1, num_ref_copies=0, num_excl_copies=0, lim={flags=0, max_rfer=0, max_excl=0, rsv_rfer=0, rsv_excl=0}, ...}, name="snapshot"}) = -1 ENOENT (No such file or directory)

I also see /var/log/snapper.log says:

2024-04-14 15:51:26 MIL libsnapper(2379408) Snapshot.cc(read):344 - found 3 snapshots
2024-04-14 15:51:26 WAR libsnapper(2379408) FileUtils.cc(SDir):88 - THROW: open failed path://.snapshots/3 errno:2 (No such file or directory)
2024-04-14 15:51:26 WAR libsnapper(2379408) Btrfs.cc(checkSnapshot):490 - CAUGHT: open failed path://.snapshots/3 errno:2 (No such file or directory)
2024-04-14 15:51:26 WAR libsnapper(2379408) Btrfs.cc(checkSnapshot):490 - CAUGHT: open failed path://.snapshots/3 errno:2 (No such file or directory)
2024-04-14 15:51:26 WAR libsnapper(2379408) FileUtils.cc(SDir):63 - THROW: open failed path:/usr/lib/snapper/plugins errno:2 (No such file or directory)
2024-04-14 15:51:26 WAR libsnapper(2379408) PluginsImpl.cc(run_scripts):68 - CAUGHT: open failed path:/usr/lib/snapper/plugins errno:2 (No such file or directory)
2024-04-14 15:51:26 ERR libsnapper(2379408) Btrfs.cc(createSnapshot):328 - create snapshot failed, btrfs_util_create_snapshot_fd2() failed, errno:2 (No such file or directory)
2024-04-14 15:51:26 WAR libsnapper(2379408) Btrfs.cc(createSnapshot):329 - THROW: create snapshot failed
2024-04-14 15:51:26 WAR libsnapper(2379408) Snapshot.cc(createHelper):780 - CAUGHT: create snapshot failed
2024-04-14 15:51:26 WAR libsnapper(2379408) Snapshot.cc(createHelper):785 - RETHROW: create snapshot failed
2024-04-14 15:51:26 WAR libsnapper(2379408) Client.cc(dispatch):1983 - CAUGHT: create snapshot failed

... which is interesting, because I do not in fact have three snapshots.

$ ls -l /.snapshots

total 4
drwxr-xr-x 1 root root 32 Jun 17  2023 1
drwxr-xr-x 1 root root 32 Apr 14 15:27 2

$ btrfs subvol list /

ID 256 gen 4562185 top level 5 path @
ID 258 gen 6455533 top level 256 path @/var
ID 259 gen 6455476 top level 256 path @/usr/local
ID 262 gen 6455532 top level 256 path @/root
ID 263 gen 6447278 top level 256 path @/opt
ID 266 gen 6455533 top level 256 path @/.snapshots
ID 353 gen 6455476 top level 258 path @/var/lib/machines
ID 75047 gen 6455533 top level 256 path @/vms
ID 92562 gen 6455533 top level 266 path @/.snapshots/1/snapshot
ID 109021 gen 6455482 top level 266 path @/.snapshots/2/snapshot

$ snapper list

 # | Type   | Pre # | Date                     | User | Cleanup | Description | Userdata
---+--------+-------+--------------------------+------+---------+-------------+---------
0  | single |       |                          | root |         | current     |         
1* | single |       | Sat Jun 17 01:47:16 2023 | root |         |             |         
2  | single |       | Sun Apr 14 15:27:39 2024 | root |         |             |         

---

Here's a working strace log from running snapper create which successfully creates the snapshot:

Apr 14 16:04:42 futaba strace[2395787]: [pid 2397633] openat(AT_FDCWD, "/", O_RDONLY|O_NOATIME|O_CLOEXEC) = 6
Apr 14 16:04:42 futaba strace[2395787]: [pid 2397633] openat(AT_FDCWD, "/", O_RDONLY|O_NOATIME|O_CLOEXEC) = 7
Apr 14 16:04:42 futaba strace[2395787]: [pid 2397633] ioctl(7, BTRFS_IOC_SNAP_CREATE_V2, {fd=6, flags=BTRFS_SUBVOL_RDONLY, name="snapshot"} => {transid=0}) = 0

[Arnavion]

The difference between the ioctl(BTRFS_IOC_SNAP_CREATE_V2) that succeeds and the one that fails is that the failing one specifies BTRFS_SUBVOL_QGROUP_INHERIT and num_qgroups = 1, even though my / does not have quota enabled.

$ btrfs qgroup show /

ERROR: can't list qgroups: quotas not enabled

https://github.com/gregkh/linux/commits/v6.8.4/fs/btrfs/ioctl.c -> gregkh/linux@f19dad4 adds an error path for ENOENT if the qgroup doesn't exist. It might be the reason.

[pallaswept]

Fair enough - All I remember about 2019 was my bedroom because I'm immuno-compromised and covid was covid 😆

I think at least in my case, this can be chalked up to pilot error (read: It's my fault) because I intentionally disabled qgroups in BTRFS and never changed snapper configs... But then again, I followed SUSE doco to disable qgroups, and there was no mention of snapper there, so perhaps pilot error, perhaps not ;) I know I'm not alone in needing to disable qgroups to allow my large number of snapshots, so I suspect that others might trip over in the same way as time progresses.

Weird that it was all cool until 6.8.4, I'm sure one of you who know snapper/BTRFS better than I, will be able to make sense of that.

BTW @Arnavion especially wanted to thank you for not only sharing the result but also your troubleshooting processes, now I can add that to my mental toolkit and my future bug reports will be more useful. Thanks!

[pallaswept]

Oh I missed the second link there, yes of course. Thanks again mate.

[pallaswept]

suddenly having no new snapshots is really bad.

I sure noticed the added sense of security that snapper and BTRFS had been providing me, when it was suddenly gone. This toolchain has saved me from potential disaster recovery, three times already, it's really excellent. I really appreciate the work you've put into this tool.