restic optimize does not delete unreferenced packs

[episource]

Restic version: restic 0.1.0 (v0.1.0-147-g867fc5b), compiled at 2015-11-21 09:32:12 with go1.5.1

Observed behavior: applying restic optimize to the repository with a single "pack not referenced in any index" error from #358 broke the repository: restic check now reports numerous "pack not referenced in any index" errors. Numerous means, that the output does not fit in my screen scrollback buffer (5000 lines)!

I did not try to restore from that repo.

Expected behavior: The initial "pack not referenced in any index" is gone.

Steps to reproduce: See #358

[fd0]

Thanks for the report, this is clearly a grave bug, the optimize command should never break the repository.

[episource]

I tried to reproduce the issue with debug logging enabled but failed (partially):

• This time the "pack not referenced in any index" error did not multiply
• Optimize promises, that "The optimize command [...] removes uneeded data", but the "pack not referenced in any index" error remained

Is the assumption correct, that optimize should remove the unrefered pack?

[fd0]

Is the assumption correct, that optimize should remove the unrefered pack?

Oh yes, that's indeed a bug. Can you please run restic dump index and have a look what that unrefenced pack contains?

[episource]

$ restic -r /media/backup-intern/restic/limucs-main.repo dump indexes | grep 846c84f0035a7eee47de70379fee24280e7f09273faefb9e9609779632d2ba64
debug enabled

... returned nothing. But wasn't this expected? Doesn't the error message tell quite clearly that the pack is not referenced in any index? Think you'll have to explain in more detail...

But: The debug log attached to #358 (comment) indicates that the pack contains blobs 253c0bac and 726f46f2:

13886210:2015/11/24 22:03:31 0.000 [               Repo.savePacker] 326613 repository.go:254 save packer with 2 blobs
13886211:2015/11/24 22:03:31 0.000 [               Repo.savePacker] 326613 repository.go:268 saved as 846c84f0
13886212:2015/11/24 22:03:31 0.000 [MasterIndex.RemoveFromInFlight] 326613 master_index.go:188 removing 253c0bac from list of in flight blobs
13886213:2015/11/24 22:03:31 0.000 [MasterIndex.RemoveFromInFlight] 326613 master_index.go:188 removing 726f46f2 from list of in flight blobs
13886214:2015/11/24 22:03:31 0.000 [              Index.StoreBlobs] 326613 index.go:121 stored 2 blobs

[episource]

Here are the files these blobs belong to:

$ grep -n -C 3 -e "adding blob 253c0bac" -e "adding blob 726f46f2" restic-daten.log
13886174-2015/11/24 22:03:31 0.000 [               Repo.findPacker] 326615 repository.go:226 found packer <Packer 1 blobs, 1076406 bytes>
13886175-2015/11/24 22:03:31 1.293 [                 Archiver.Save]  55 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0012.JPG
13886176-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob e0fa9d45, 901176 bytes
13886177:2015/11/24 22:03:31 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob 253c0bac, 1970872 bytes
13886178-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob db978bbe, 699815 bytes
13886179-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob cbf12ffd, 1076374 bytes
13886180-2015/11/24 22:03:31 1.293 [             Archiver.SaveFile]  55 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0012.JPG"): 4 blobs
--
13886240-2015/11/24 22:03:31 0.871 [                 Archiver.Save] 326611 archiver.go:77 Save(data, 253c0bac): new blob
13886241-2015/11/24 22:03:31 1.271 [                 Archiver.Save]  67 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0012.JPG_original
13886242-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  67 archiver.go:167   adding blob 8241ad29, 896793 bytes
13886243:2015/11/24 22:03:31 0.000 [                 Archiver.Save]  67 archiver.go:167   adding blob 253c0bac, 1970872 bytes
13886244-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  67 archiver.go:167   adding blob db978bbe, 699815 bytes
13886245-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  67 archiver.go:167   adding blob cbf12ffd, 1076374 bytes
13886246-2015/11/24 22:03:31 1.271 [             Archiver.SaveFile]  67 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0012.JPG_original"): 4 blobs
--
13886266-2015/11/24 22:03:31 0.446 [                 Archiver.Save] 326617 archiver.go:77 Save(data, c579c121): new blob
13886267-2015/11/24 22:03:31 1.161 [                 Archiver.Save]  61 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG
13886268-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  61 archiver.go:167   adding blob 8ab44a03, 1010841 bytes
13886269:2015/11/24 22:03:31 0.052 [                 Archiver.Save]  61 archiver.go:167   adding blob 726f46f2, 2295075 bytes
13886270-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  61 archiver.go:167   adding blob c579c121, 1501380 bytes
13886271-2015/11/24 22:03:31 1.213 [             Archiver.SaveFile]  61 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG"): 3 blobs
13886272-2015/11/24 22:03:31 1.213 [           Archiver.fileWorker]  61 archiver.go:296    processed snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG, 3/0 blobs
--
13886515-2015/11/24 22:03:31 0.740 [                 Archiver.Save] 326616 archiver.go:77 Save(data, 726f46f2): new blob
13886516-2015/11/24 22:03:31 1.260 [                 Archiver.Save]  59 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG_original
13886517-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob 7e24d605, 1006698 bytes
13886518:2015/11/24 22:03:31 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob 726f46f2, 2295075 bytes
13886519-2015/11/24 22:03:31 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob c579c121, 1501380 bytes
13886520-2015/11/24 22:03:31 1.260 [             Archiver.SaveFile]  59 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG_original"): 3 blobs
13886521-2015/11/24 22:03:31 1.260 [           Archiver.fileWorker]  59 archiver.go:296    processed snapshot.current/Users/Xxxxx/Pictures/2011/Sortieren/IMG_0013.JPG_original, 3/0 blobs
--
29888678-2015/11/25 00:03:09 0.002 [                 Archiver.Save] 526942 archiver.go:66 (data, cbf12ffd) already saved
29888679-2015/11/25 00:03:09 0.731 [                 Archiver.Save]  53 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0012.JPG_original
29888680-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  53 archiver.go:167   adding blob 8241ad29, 896793 bytes
29888681:2015/11/25 00:03:09 0.000 [                 Archiver.Save]  53 archiver.go:167   adding blob 253c0bac, 1970872 bytes
29888682-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  53 archiver.go:167   adding blob db978bbe, 699815 bytes
29888683-2015/11/25 00:03:09 0.002 [                 Archiver.Save]  53 archiver.go:167   adding blob cbf12ffd, 1076374 bytes
29888684-2015/11/25 00:03:09 0.734 [             Archiver.SaveFile]  53 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0012.JPG_original"): 4 blobs
--
29888863-2015/11/25 00:03:09 0.012 [                 Archiver.Save] 526945 archiver.go:66 (data, c579c121) already saved
29888864-2015/11/25 00:03:09 0.839 [                 Archiver.Save]  63 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG
29888865-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  63 archiver.go:167   adding blob 8ab44a03, 1010841 bytes
29888866:2015/11/25 00:03:09 0.000 [                 Archiver.Save]  63 archiver.go:167   adding blob 726f46f2, 2295075 bytes
29888867-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  63 archiver.go:167   adding blob c579c121, 1501380 bytes
29888868-2015/11/25 00:03:09 0.839 [             Archiver.SaveFile]  63 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG"): 3 blobs
29888869-2015/11/25 00:03:09 0.839 [           Archiver.fileWorker]  63 archiver.go:296    processed snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG, 3/0 blobs
--
29889025-2015/11/25 00:03:09 0.002 [                 Archiver.Save] 526928 archiver.go:66 (data, 253c0bac) already saved
29889026-2015/11/25 00:03:09 1.055 [                 Archiver.Save]  55 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG_original
29889027-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob 7e24d605, 1006698 bytes
29889028:2015/11/25 00:03:09 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob 726f46f2, 2295075 bytes
29889029-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  55 archiver.go:167   adding blob c579c121, 1501380 bytes
29889030-2015/11/25 00:03:09 1.055 [             Archiver.SaveFile]  55 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG_original"): 3 blobs
29889031-2015/11/25 00:03:09 1.055 [           Archiver.fileWorker]  55 archiver.go:296    processed snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0013.JPG_original, 3/0 blobs
--
29889108-2015/11/25 00:03:09 0.002 [                 Archiver.Save] 526947 archiver.go:66 (data, db978bbe) already saved
29889109-2015/11/25 00:03:09 1.308 [                 Archiver.Save]  59 archiver.go:158 checking size for file /snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0012.JPG
29889110-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob e0fa9d45, 901176 bytes
29889111:2015/11/25 00:03:09 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob 253c0bac, 1970872 bytes
29889112-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob db978bbe, 699815 bytes
29889113-2015/11/25 00:03:09 0.000 [                 Archiver.Save]  59 archiver.go:167   adding blob cbf12ffd, 1076374 bytes
29889114-2015/11/25 00:03:09 1.308 [             Archiver.SaveFile]  59 archiver.go:174 SaveFile("/snapshots/daten/snapshot.current/Users/Yyyyyyy/Pictures/Fotos/2011/Schweden/IMG_0012.JPG"): 4 blobs

[fd0]

What I'd really like to find out it why running optimize caused more unreferenced packs to appear. That's really strange, I'm not able to reproduce it.

[episource]

Me neither. This time "only" the one unreferenced pack remains. Sadly I deleted the initial repo in order for a new run with debug logging enabled.

I could start over again with a refresh repo. With some luck this allows me to reproduce the initial error...

[fd0]

Hm. I'll have a look at the optimize code again this weekend, to see if I can spot anything that might lead to such a bad result.

[episource]

Well, I started over twice with the following results:

• Existing unreferenced packs were not deleted by restic optimize
• No additional unreferenced packs appeared

Conclusion: I would consider this issue as initially reported unreproduceable. You could rename the issue to "restic optimize does not delete unreferenced packs".

[episource]

I looked up in my shell's history, the exact commands I executed monday morning: check, unlock, check, optimize, check. I forgot to write about the unlock. I cannot explain why the first check failed to lock the repository. I'm quite sure that no other restic instance was running, but who knows... it was early monday morning...

[fd0]

I've updated the title. Do you think there is a different issue that the one described in #358? Or should we close this one for now?

[episource]

I think both issues are still different: #358 causes unreferenced packs, where as this issue is about optimize not cleaning them up.

[fd0]

Ok, I'll have a look.

[viric]

As an additional note, it is a bit disturbing that "restic check" considers that having unreferefenced packs means that "the respository has errors". It does not seem like an error to me; maybe it could just point to optimize.

[fd0]

Good point, thanks.

[fd0]

The optimize command was replaced by the prune command which does not have this bug, closing.