snapper-clearnup.service issues from 20221101 still exist in 20221202
The snapper-cleanup.service appears as a failed service listed by systemd --failed Manually running the command which the service runs: /usr/lib/snapper/systemd-helper --cleanup running cleanup for 'home'. running number cleanup for 'home'. running timeline cleanup for 'home'. running empty-pre-post cleanup for 'home'. running cleanup for 'root'. running number cleanup for 'root'. Failure (error.something). number cleanup for 'root' failed. running timeline cleanup for 'root'. running empty-pre-post cleanup for 'root'. Note the "Failure (error.something)." which is not real helpful :-) The only additional info in the journal is: Dec 04 16:18:09 DadPC.fios-router.home systemd[1]: snapper-cleanup.service: Main process exited, code=exited, status=1/FAILURE Dec 04 16:18:09 DadPC.fios-router.home systemd[1]: snapper-cleanup.service: Failed with result 'exit-code'. Looking at the snapshots for root and home it DOES appear that the snapshots are actually being cleaned up because the correct number of snapshots for each config is being maintained so it is not clear exactly what it is having a problem with???
On Sun, 04 Dec 2022 22:26:17 -0000, "Joe Salmeri"
The snapper-cleanup.service appears as a failed service listed by systemd --failed
Manually running the command which the service runs:
/usr/lib/snapper/systemd-helper --cleanup
running cleanup for 'home'. running number cleanup for 'home'. running timeline cleanup for 'home'. running empty-pre-post cleanup for 'home'. running cleanup for 'root'. running number cleanup for 'root'. Failure (error.something). number cleanup for 'root' failed. running timeline cleanup for 'root'. running empty-pre-post cleanup for 'root'.
Note the "Failure (error.something)." which is not real helpful :-)
The only additional info in the journal is:
Dec 04 16:18:09 DadPC.fios-router.home systemd[1]: snapper-cleanup.service: Main process exited, code=exited, status=1/FAILURE Dec 04 16:18:09 DadPC.fios-router.home systemd[1]: snapper-cleanup.service: Failed with result 'exit-code'.
Looking at the snapshots for root and home it DOES appear that the snapshots are actually being cleaned up because the correct number of snapshots for each config is being maintained so it is not clear exactly what it is having a problem with???
Does /var/log/snapper.log show anything? This is not the same, I assume you would have noticed filesystem problems, but check out: "Failure (error.something)." when calling snapper -v cleanup number in a system with broken filesystem #686 https://github.com/openSUSE/snapper/issues/686 -- Robert Webb
Hi Robert, Not sure what you mean by "this is not the same". Whether the service runs that command or I run it from the cmdline they produce the same results the only difference are those 2 journal messages which only come out when the service runs. I am not having any filesystem problems and running a btrfs device stats as well as btrfs scrub report no errors or issues. I use this system daily for 12+ hours a day so since it first started with TW 20221101 ( 5 weeks ago ) and still exists in 20221202 it seems to reason that if something was really failing it would have failed by now based on all the other times I've ever had a drive fail. Certainly btrfs should be reporting something is wrong. Looking at /var/log/snapper.log ( thanks for that pointer ) I see: 2022-12-04 19:11:11 MIL libsnapper(17833) Snapper.cc(Snapper):130 - subvolume:/home filesystem:btrfs 2022-12-04 19:11:11 MIL libsnapper(17833) Snapper.cc(loadIgnorePatterns):204 - number of ignore patterns:8 2022-12-04 19:11:11 MIL libsnapper(17833) Snapshot.cc(read):288 - found 18 snapshots 2022-12-04 19:11:11 WAR libsnapper(17833) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:11:11 WAR libsnapper(17833) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:11:41 MIL libsnapper(17833) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-04 19:12:11 MIL libsnapper(17833) snapperd.cc(main):315 - Exiting 2022-12-04 19:13:03 MIL libsnapper(17950) snapperd.cc(main):283 - Requesting DBus name 2022-12-04 19:13:03 MIL libsnapper(17950) snapperd.cc(main):298 - Loading snapper configs 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(getConfigs):299 - Snapper get-configs 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(getConfigs):300 - libsnapper version 0.10.3 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(reload):922 - loading file /etc/sysconfig/snapper 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SNAPPER_CONFIGS value:root home 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/root 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/ 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/home 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/home 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:ALLOW_USERS value: 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:ALLOW_GROUPS value: 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:ALLOW_USERS value: 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:ALLOW_GROUPS value: 2022-12-04 19:13:03 MIL libsnapper(17950) snapperd.cc(main):311 - Listening for method calls and signals 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):95 - Snapper constructor 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):96 - libsnapper version 0.10.3 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):97 - config_name:home disable_filters:false 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/home 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/home 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:FSTYPE value:btrfs 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:QGROUP value: 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SYNC_ACL value:no 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):130 - subvolume:/home filesystem:btrfs 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(loadIgnorePatterns):204 - number of ignore patterns:8 2022-12-04 19:13:03 MIL libsnapper(17950) Snapshot.cc(read):288 - found 18 snapshots 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):95 - Snapper constructor 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):96 - libsnapper version 0.10.3 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):97 - config_name:root disable_filters:false 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(reload):922 - loading file /etc/snapper/configs/root 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SUBVOLUME value:/ 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:FSTYPE value:btrfs 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:QGROUP value:1/0 2022-12-04 19:13:03 MIL libsnapper(17950) AsciiFile.cc(get_value):1078 - key:SYNC_ACL value:no 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(Snapper):130 - subvolume:/ filesystem:btrfs 2022-12-04 19:13:03 MIL libsnapper(17950) Snapper.cc(loadIgnorePatterns):204 - number of ignore patterns:8 2022-12-04 19:13:03 MIL libsnapper(17950) Snapshot.cc(read):288 - found 4 snapshots 2022-12-04 19:13:17 ERR libsnapper(17950) Client.cc(dispatch):1951 - caught unknown exception 2022-12-04 19:13:17 WAR libsnapper(17949) errors.cc(convert_exception):39 - CAUGHT: dbus error exception 2022-12-04 19:13:17 WAR libsnapper(17949) errors.cc(convert_exception):52 - RETHROW: dbus error exception 2022-12-04 19:13:33 MIL libsnapper(17950) Snapper.cc(~Snapper):142 - Snapper destructor The home snapshot ( /home/.snapshots/1 ) it refers too has not existed for close to 2 years since my home snapper config does timeline snapshots but only keeps the last 10 hours and the last 5 days. Not sure if those errors then cause the dbus error exception messages but clearly something in the cleanup process is broken if it is looking for something that hasn't existed in 2 years. Running the following ( from the github link you provided ) snapper -v -c home cleanup timeline Produces no output or errors but if I watch /var/log/snapper.log it gets the following 2022-12-04 19:32:15 WAR libsnapper(18407) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:32:15 WAR libsnapper(18407) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) When you consider that there are no filesystem errors being reported by btrfs ( nor anything else ) and also that the timeline snapshots for the home config are being cleaned up properly it would seem that other than the attempt to access home snapshot #1 which has not existed for 2 years that it is working properly. Any other thoughts? Thanks!
On Mon, 05 Dec 2022 00:41:00 -0000, "Joe Salmeri"
Not sure what you mean by "this is not the same".
The issue in [1] is not the same as yours because they had a broken filesystem, but their problem did involve 'snapper cleanup number' with the same generic error message you got.
Whether the service runs that command or I run it from the cmdline they produce the same results the only difference are those 2 journal messages which only come out when the service runs.
The "DadPC.fios-router.home" in the journal is not referring to your home partition, right?
[... (no apparent filesystem problems)]
Looking at /var/log/snapper.log ( thanks for that pointer ) I see:
[...] 2022-12-04 19:11:11 WAR libsnapper(17833) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:11:11 WAR libsnapper(17833) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:11:41 MIL libsnapper(17833) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-04 19:12:11 MIL libsnapper(17833) snapperd.cc(main):315 - Exiting
[...] 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:13:03 WAR libsnapper(17950) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory)
[...] 2022-12-04 19:13:17 ERR libsnapper(17950) Client.cc(dispatch):1951 - caught unknown exception 2022-12-04 19:13:17 WAR libsnapper(17949) errors.cc(convert_exception):39 - CAUGHT: dbus error exception 2022-12-04 19:13:17 WAR libsnapper(17949) errors.cc(convert_exception):52 - RETHROW: dbus error exception 2022-12-04 19:13:33 MIL libsnapper(17950) Snapper.cc(~Snapper):142 - Snapper destructor
The home snapshot ( /home/.snapshots/1 ) it refers too has not existed for close to 2 years since my home snapper config does timeline snapshots but only keeps the last 10 hours and the last 5 days.
I have little experience with snapper, and it has been a long time since I read the docs, but isn't snapshot #1 special in some way?
Not sure if those errors then cause the dbus error exception messages but clearly something in the cleanup process is broken if it is looking for something that hasn't existed in 2 years.
Running the following ( from the github link you provided )
snapper -v -c home cleanup timeline
Produces no output or errors but if I watch /var/log/snapper.log it gets the following
2022-12-04 19:32:15 WAR libsnapper(18407) FileUtils.cc(SDir):91 - THROW: open failed path:/home/.snapshots/1 errno:2 (No such file or directory) 2022-12-04 19:32:15 WAR libsnapper(18407) Btrfs.cc(checkSnapshot):482 - CAUGHT: open failed path:/home/.snapshots/1 errno:2 (No such file or directory)
Your output from '/usr/lib/snapper/systemd-helper --cleanup' showed that "Failure (error.something)" happened during "number cleanup for 'root'". Instead of 'snapper -v -c home cleanup timeline', how about trying 'snapper -v -c root cleanup number' ?
When you consider that there are no filesystem errors being reported by btrfs ( nor anything else ) and also that the timeline snapshots for the home config are being cleaned up properly it would seem that other than the attempt to access home snapshot #1 which has not existed for 2 years that it is working properly.
Any other thoughts? Thanks!
Run strace like they did in [1] to find what leads to the "Failure (error.something)." [1] https://github.com/openSUSE/snapper/issues/686 -- Robert Webb
Hi Robert, I just did another test. I have a TW VM which is stored on a different physical drive. Running in that VM /usr/lib/snapper/systemd-helper --cleanup Also produces similar errors: Failure (error.something). number cleanup for 'root' failed. And /var/log/snapper.log in the VM also contains similar errors: 2022-12-04 20:06:27 ERR libsnapper(2289) Client.cc(dispatch):1951 - caught unknown exception 2022-12-04 20:06:27 WAR libsnapper(2437) errors.cc(convert_exception):39 - CAUGHT: dbus error exception 2022-12-04 20:06:27 WAR libsnapper(2437) errors.cc(convert_exception):52 - RETHROW: dbus error exception 2022-12-04 20:06:42 MIL libsnapper(2289) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-04 20:06:57 MIL libsnapper(2289) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-04 20:07:27 MIL libsnapper(2289) snapperd.cc(main):315 - Exiting So we have similar snapper errors from different TW installs on different physical disks. Seems pretty unlikely that all my drives are falling....
Hi,
you can try the latest packages from
https://build.opensuse.org/project/show/filesystems:snapper
(which have better logging) and report via bugzilla.
ciao
Arvin
--
Arvin Schnell,
Hi Arvin, I installed snapper-0.10.3-8.1.x86_64.rpm from the location you provided into a test VM which also had the same problem as the host machine. Running /usr/lib/snapper/systemd-helper --cleanup running cleanup for 'home'. running number cleanup for 'home'. running timeline cleanup for 'home'. running empty-pre-post cleanup for 'home'. running cleanup for 'root'. running number cleanup for 'root'. quota not working (preparing quota failed) running timeline cleanup for 'root'. running empty-pre-post cleanup for 'root'. That got rid of the error messages although not sure why it says quota is not working because 'snapper -c home ls' shows the space used by each snapshot and it would not if quota was not enabled. So that resolves the 'Failure (error.something).' message that was coming from /usr/lib/snapper/systemd-helper --cleanup but when I look at /var/log/snapper.log it seems that it is still having issues with that latest snapper rpm as it has: 2022-12-05 11:06:00 WAR libsnapper(3345) Snapper.cc(prepareQuota):791 - THROW: preparing quota failed 2022-12-05 11:06:00 WAR libsnapper(3345) Client.cc(dispatch):1921 - CAUGHT: preparing quota failed 2022-12-05 11:06:00 WAR libsnapper(3398) errors.cc(convert_exception):39 - CAUGHT: dbus error exception 2022-12-05 11:06:00 WAR libsnapper(3398) errors.cc(convert_exception):47 - THROW: preparing quota failed 2022-12-05 11:06:00 WAR libsnapper(3398) cleanup.cc(is_quota_aware):264 - CAUGHT: preparing quota failed 2022-12-05 11:06:00 MIL libsnapper(3345) Snapper.cc(queryFreeSpaceData):899 - size:527636103168 free:487053434880 2022-12-05 11:06:00 MIL libsnapper(3345) Snapper.cc(queryFreeSpaceData):899 - size:527636103168 free:487053434880 2022-12-05 11:06:00 MIL libsnapper(3345) Comparison.cc(Comparison):60 - num1:4 num2:5 2022-12-05 11:06:00 MIL libsnapper(3345) Comparison.cc(load):272 - num1:4 num2:5 2022-12-05 11:06:00 MIL libsnapper(3345) Comparison.cc(load):256 - read 7 lines 2022-12-05 11:06:30 MIL libsnapper(3345) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-05 11:06:30 MIL libsnapper(3345) Snapper.cc(~Snapper):142 - Snapper destructor 2022-12-05 11:07:00 MIL libsnapper(3345) snapperd.cc(main):315 - exiting So it would appear the original issue is fixed but now there is a bug regarding quota. Or possibly it was not getting to the quota part of the code with the initial bug. Despite the error it still seems to be properly cleaning up the timeline snapshots. Joe
participants (3)
-
Arvin Schnell -
Joe Salmeri -
Robert Webb