BackBlaze prune failing to process?

I’ve got a new issue as of last night, prune on BackBlaze storage fails to fully run, it hung up at 5:45AM and has been sitting at the same line in the log for hours.

Trying to re-run it now and I get stopped within a moment each time I try to run it.
It ends up being a different backup that the prune is running where it stops, but it’s always revision 65 for some reason…
Weird, but can’t seem to find out what is going wrong and how to fix this?

Running prune command from /cache/localhost/all
Options: [-log prune -storage Backblaze -keep 0:15 -all -exhaustive]
2021-01-27 09:23:20.630 INFO STORAGE_SET Storage set to b2://****************
2021-01-27 09:23:21.111 INFO BACKBLAZE_URL download URL is: https://f002.backblazeb2.com
2021-01-27 09:23:22.105 INFO RETENTION_POLICY Keep no snapshots older than 15 days
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 15
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 16
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 17
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 18
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 19
2021-01-27 09:23:31.518 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 20
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 60
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 61
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 62
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 63
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 64
2021-01-27 09:23:31.537 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 65
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 61
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 62
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 63
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 64
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 65
2021-01-27 09:23:32.081 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 66
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 60
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 61
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 62
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 63
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 64
2021-01-27 09:23:32.427 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 65
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 64
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 65
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 66
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 67
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 68
2021-01-27 09:23:33.390 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 69
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 60
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 61
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 62
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 63
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 64
2021-01-27 09:23:33.404 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 65

Check the main log ~/.duplicacy-web/logs/duplicacy_web.log. It could be that the processes were killed due to out of memory.

thanks, looks like that happend during the overnight run, the other recent ones I had I think i was being impateint on :wink: they ended up finishing normally after some time.

Ok so I am having the same issue today again, the prune is running and the trailing log file ends with

2021-02-01 05:38:50.398 INFO CHUNK_DELETE The chunk 3a6558c66a16a507ff179ed04fa3133efa6efc3fad2d63dbc565f923c40f7fa8 has been permanently removed
2021-02-01 05:38:51.289 INFO CHUNK_DELETE The chunk 123b0d2b54afb0613239ec312018f304f051a92fd7ae35bbd3d17d142bac7623 has been permanently removed
2021-02-01 05:38:52.153 INFO CHUNK_DELETE The chunk 8db287da4fb4ad0de2e18fea9090f1663569a4691ee184eb8e0738884c9e3878 has been permanently removed
2021-02-01 05:38:53

It just ends with a partial timestamp, and that was at ~5:30AM, it’s now 1PM, so in nearly 8 hours it hasn’t done anything?

And my ~/.duplicacy-web/logs/duplicacy_web.log shows the following.

2021/02/01 05:19:34 Created log file /logs/prune-20210201-051934.log
2021/02/01 05:19:34 Running /root/.duplicacy-web/bin/duplicacy_linux_x64_2.7.2 [-log prune -storage Backblaze -keep 0:15 -all]
2021/02/01 05:19:34 Set current working directory to /cache/localhost/all
(some GET commands of when i'm using the web UI, deleting some old backup logs, etc)

Then nothing, not sure what’s going on… Would like to get to the bottom of this though, as it’s killing my automated backups.

Actually, if I go check the actual prune-2021-0201-051934.log file it shows a few more lines, but it still stops running at ~5:30AM - there’s nothing else in any log that I can see that shows the prune was termianted. The web UI still thinks its running but there hasnt’ been a single line logged since this last one @ 5:38AM, it’s not over 10 hours later.

How can I troubleshoot/fix this?
PS the system it’s running on has 128GB of RAM, so it shouldn’t be running out of memory on a prune.

2021-02-01 05:38:54.958 INFO CHUNK_DELETE The chunk 3e8715a7e37dc1740b61637942b3486828585a406f1a1b6519235a6f3a7a5f9d has been permanently removed
2021-02-01 05:38:55.856 INFO CHUNK_DELETE The chunk 206a1729aac5f9becec096d9bd1d86cc6388bb0ac25011a45528fb2afcde6b1c has been permanently removed
2021-02-01 05:38:56.800 INFO CHUNK_DELETE The chunk e0d4dfc882edb4b554e18b627a7da6937cecb536948cbd58d33bae5458b8faed has been permanently removed
2021-02-01 05:38:57.824 INFO CHUNK_DELETE The chunk c011c791f17f9723324995551a1866f557c747b84322ac0abcbf71835e76ef87 has been permanently removed
2021-02-01 05:38:58.696 INFO CHUNK_DELETE The chunk 63cd56b4b9f9f3f05332732e597059e4b56c449ba4bba2bf7b3aaaf2e66ef3df has been permanently removed

I cancelled tbhat after nearly 11 hours of it not doing anything and started a new one and it seems to lock up agian right away this time.

Nothing logged anywehre about the process crashing either.

Running prune command from /cache/localhost/all
Options: [-log prune -storage Backblaze -keep 0:15 -all -exhaustive]
2021-02-01 15:49:02.228 INFO STORAGE_SET Storage set to b2://************
2021-02-01 15:49:02.652 INFO BACKBLAZE_URL download URL is: https://f002.backblazeb2.com
2021-02-01 15:49:04.782 INFO RETENTION_POLICY Keep no snapshots older than 15 days
2021-02-01 15:49:11.795 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 74
2021-02-01 15:49:11.847 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 70
2021-02-01 15:49:12.318 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 25
2021-02-01 15:49:12.337 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 70
2021-02-01 15:49:12.865 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 71
2021-02-01 15:49:13.297 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 70

Update, prune from my last post finally finished but there was a 4 hour pause for some reason.

Still no idea why my initial one was stuck for 11 hours (2nd time in the past week)

Running prune command from /cache/localhost/all
Options: [-log prune -storage Backblaze -keep 0:15 -all -exhaustive]
2021-02-01 15:49:02.228 INFO STORAGE_SET Storage set to b2://**********
2021-02-01 15:49:02.652 INFO BACKBLAZE_URL download URL is: https://f002.backblazeb2.com
2021-02-01 15:49:04.782 INFO RETENTION_POLICY Keep no snapshots older than 15 days
2021-02-01 15:49:11.795 INFO SNAPSHOT_DELETE Deleting snapshot Flash at revision 74
2021-02-01 15:49:11.847 INFO SNAPSHOT_DELETE Deleting snapshot Nextcloud at revision 70
2021-02-01 15:49:12.318 INFO SNAPSHOT_DELETE Deleting snapshot Paperless at revision 25
2021-02-01 15:49:12.337 INFO SNAPSHOT_DELETE Deleting snapshot Photos at revision 70
2021-02-01 15:49:12.865 INFO SNAPSHOT_DELETE Deleting snapshot AppData at revision 71
2021-02-01 15:49:13.297 INFO SNAPSHOT_DELETE Deleting snapshot Backups at revision 70
2021-02-01 19:18:16.210 INFO FOSSIL_COLLECT Fossil collection 1 saved
2021-02-01 19:18:16.714 INFO SNAPSHOT_DELETE The snapshot Photos at revision 70 has been removed
2021-02-01 19:18:17.274 INFO SNAPSHOT_DELETE The snapshot AppData at revision 71 has been removed
2021-02-01 19:18:17.768 INFO SNAPSHOT_DELETE The snapshot Backups at revision 70 has been removed
2021-02-01 19:18:18.248 INFO SNAPSHOT_DELETE The snapshot Flash at revision 74 has been removed
2021-02-01 19:18:18.764 INFO SNAPSHOT_DELETE The snapshot Nextcloud at revision 70 has been removed
2021-02-01 19:18:19.254 INFO SNAPSHOT_DELETE The snapshot Paperless at revision 25 has been removed

Can you add -d as a global option to the prune job? This may show additional log messages that would otherwise be ignored by default.

ok, will give that a try and report back on next run where it seemingly locks up for a few hours.