npbackup-cli incorrect backup attempt and runner.py stacktrace

[GuitarBilly]

npbackup 3.0.1-linux-cli-x64-public-3.12-c 2025032101
ubuntu 22.10

steps to reproduce

I have set up npbackup-cli to replace a daily backup that was done at 02:00 hrs.
But I forgot this was done in the 'standard' npbackup-gui cron job at /etc/cron.d/npbackup which runs every 15 minutes.

That will conflict with another restic repo check job that was still run at 04:00 via root crontab -l and 385msec faster 8-) :
00 4 * * 0-5 /path/to/cronscripts/hc.syncthing.restic_check.sh

So npbackup reported a fail in the Grafana dashboard at 04:00 and looking in the log I first see some expected repo locked conflicts. This is bacause the other restic check job runs on the same repo.
Npbackup-cli then concludes "cannot find backup" and somehow still wants to start a backup at the locked repo and then bombs out what looks to be during the metrics collection phase into a runner.py stack trace:

npbackup-cli.log

expected behaviour

1. npbackup should not start to backup on a locked repo.
2. npbackup should not crash in the scenario of a locked repo.

p.s. I will change the npbackup cron job to run once daily as I had it in my prior setup.

[deajan]

So far, the metrics bug has been corrected last month already in 3f1dfb0

As for the locking, you're right, npbackup shoudln't acquire a lock for snapshots listing.

Thanks for the report.

[GuitarBilly]

@Deejan, I think you misunderstand my issue with the lock. snapshots are not a problem, but ignoring the lock and trying to initialize and start the backup is in my opinion.

SUMMARY

If you look in the log file:
npbackup detects the lock from restic at line 26. AGREE
npbackup concludes there is no prior backup at line 37. DISAGREE, because repo was locked.
but previous result causes npbackup to start a backup which fails, because the repo is still locked by restic at line 49.

CONCLUSION

if the first contact returns a locked repo, npbackup should either abort or retry. but never continue to initialize or backup to the repo.

[deajan]

@GuitarBilly I think you misunderstand my resolution

In order to check for existing backups, npbackup tries to retrieve snapshots, which it did previously while trying to acquire locks.
Since this step failed, npbackup concluded that there are no recent snapshots, hence tries to create a new one (which fails since repo is still locked, but this is normal behavoir).

So I removed the locking requirement for snapshots, which indeed should resolve the problem.

Does this satisfy the question or is it "more complicated" ?

[GuitarBilly]

@deajan yes I think I cannot envision your solution.
But I can and will verify that with your updated code against a locked repo.

That will be planned in a few days from now as I first want to confirm another cron behaviour with this repo and I will run it on my one machine which I've set up to run the latest github code.

[GuitarBilly]

Actually I had some time tonight so I ran a trial on the latest code. I ran a restic check --read-data and then launched a npbackup backup after a few seconds on the same repository.

Caveat - I have run with npbackup-gui via the GUI and not with npbackup-cli.

terminal log:

npbackup 3.0.2-linux-gui-x64-legacy-public-3.10-i 2025050201 - Copyright (C) 2022-2025 NetInvent running as linux
2025-05-12 23:55:18,228 :: INFO :: Using binary restic 0.18.0 compiled with go1.24.1 on linux/amd64
2025-05-12 23:55:18,228 :: INFO :: Running backup of ['/home/ubuntu/containers/redacted'] to repo redacted
2025-05-12 23:55:18,228 :: ERROR :: Path /home/ubuntu/containers/redacted does not exist or is not readable
2025-05-12 23:55:18,228 :: ERROR :: Not all files/folders are present in backup source
2025-05-12 23:55:19,068 :: ERROR :: repo already locked, waiting up to 0s for the lock
unable to create lock in backend: repository is already locked exclusively by PID 2060477 on redacted by root (UID 0, GID 0)
lock was created at 2025-05-12 23:55:13 (5.460740915s ago)
storage ID d32728ea
the `unlock` command can be used to remove stale locks

2025-05-12 23:55:19,068 :: ERROR :: Backend failed operation:
repo already locked, waiting up to 0s for the lock
unable to create lock in backend: repository is already locked exclusively by PID 2060477 on redacted by root (UID 0, GID 0)
lock was created at 2025-05-12 23:55:13 (5.460740915s ago)
storage ID d32728ea
the `unlock` command can be used to remove stale locks

2025-05-12 23:55:19,068 :: ERROR :: Cannot find processed bytes: Given string "None" cannot be converted to bytes
2025-05-12 23:55:19,083 :: INFO :: Metrics pushed successfully.
2025-05-12 23:55:19,084 :: INFO :: Operation finished with success
2025-05-12 23:55:19,084 :: INFO :: Runner took 0.914473 seconds for backup
2025-05-12 23:55:51,963 :: INFO :: Using binary restic 0.18.0 compiled with go1.24.1 on linux/amd64
2025-05-12 23:55:51,963 :: INFO :: Listing snapshots of repo redacted
2025-05-12 23:55:52,634 :: INFO :: Snapshots listed successfully
2025-05-12 23:55:52,634 :: INFO :: Runner took 0.729077 seconds for snapshots
2025-05-12 23:55:52,639 :: INFO :: Metrics pushed successfully.
2025-05-12 23:55:52,853 :: INFO :: Recent snapshot ab0ae06a of 2025-05-12T03:00:01.979516237+02:00 exists !

npbackup does not crash, but still an error on the metrics is present?
( 2025-05-12 23:55:19,068 :: ERROR :: Cannot find processed bytes: Given string "None" cannot be converted to bytes )

[deajan]

Indeed, I should only log that as debug statement. Done.
Thank you for all the time you spend doing that debugging.