[Borgbackup] borg 1.0.3 crashes on prune

[Hans-Peter Jansen]

On Montag, 27. Juni 2016 17:43:45 Thomas Waldmann wrote:
> >> $ borg prune -v --list --keep-daily=7 --keep-weekly=4
> >> --keep-monthly=12 --prefix server-vbox /backup/borg
> >> ...
> >> Object with key
> >> b'\x91\xd9\xd0\xde\xad\xfaz\xeeEL\xef\x80\x1c?\xfeX"\xcf\xa8\xfe2\x14\xec
> >> \xe4\x89\xacy\x97}~\xf1y' not found in repository /backup/borg.
> 
> The object seems to be not in the repo.
> 
> >> Traceback (most recent call last):
> >>   File "/usr/lib64/python3.4/site-packages/borg/archiver.py", line
> >> 
> >> 610, in do_prune
> >> 
> >>     Archive(repository, key, manifest, archive.name, cache).delete(stats)
> >>   
> >>   File "/usr/lib64/python3.4/site-packages/borg/archive.py", line 450,
> >> 
> >> in delete
> >> 
> >>     self.cache.chunk_decref(chunk_id, stats)
> >>   
> >>   File "/usr/lib64/python3.4/site-packages/borg/cache.py", line 392,
> >> 
> >> in chunk_decref
> >> 
> >>     self.repository.delete(id, wait=False)
> >>   
> >>   File "/usr/lib64/python3.4/site-packages/borg/repository.py", line
> >> 
> >> 476, in delete
> >> 
> >>     raise self.ObjectNotFound(id, self.path) from None
> >> 
> >> borg.repository.ObjectNotFound:
> >> (b'\x91\xd9\xd0\xde\xad\xfaz\xeeEL\xef\x80\x1c?\xfeX"\xcf\xa8\xfe2\x14\xe
> >> c\xe4\x89\xacy\x97}~\xf1y', '/backup/borg')
> 
> Strange, that (obviously) should not happen.
> 
> It decremented the reference counter in the chunks index, found it 0,
> then (successfully) deleted the entry from the chunks index, then tried
> to delete the (now unused) object from the repo, but it was not there -
> boom.
> 
> So, it looks like the index and repo contents did not agree.
> 
> Can it be that 2 borgs accidentally wrote to the repo in parallel
> because you manually broke the lock (borg break-lock)?
> 
> Were there any issues before this one when accessing the backup repo?

No, none I'm aware of.

> >> '/backup/borg']
> 
> Is that the correct repo path? Is it a local device or via network
> somehow? How?

Yes, of course. It's a local path to a harddisk, dedicated for backup with a single XFS filesystem. (Checked it yesterday for other reasons)

> If via network: did you have network interruptions while writing to the
> repo?

I've suffered from a nightly crash lately, which could be the reason.

> borg check -v might be a good idea now. check its result.

Analyzing archive client-vmware-2016-06-27 (28/28)
Analyzing archive server-vmware-2016-06-27 (27/28)
Analyzing archive server-vbox-2016-06-26 (26/28)
Analyzing archive client-vmware-2016-06-26 (25/28)
Analyzing archive server-vmware-2016-06-26 (24/28)
Analyzing archive server-vbox-2016-06-25 (23/28)
Analyzing archive client-vmware-2016-06-25 (22/28)
Analyzing archive server-vmware-2016-06-25 (21/28)
Analyzing archive server-vbox-2016-06-24 (20/28)
Analyzing archive client-vmware-2016-06-24 (19/28)
Analyzing archive server-vmware-2016-06-24 (18/28)
Analyzing archive server-vbox-2016-06-23 (17/28)
Analyzing archive client-vmware-2016-06-23 (16/28)
Analyzing archive server-vbox-2016-06-22 (15/28)
Analyzing archive client-vmware-2016-06-22 (14/28)
Analyzing archive server-vmware-2016-06-22 (13/28)
Analyzing archive server-vbox-2016-06-21 (12/28)
Analyzing archive client-vmware-2016-06-21 (11/28)
Analyzing archive server-vmware-2016-06-21 (10/28)
Analyzing archive server-vbox-2016-06-20 (9/28)
Analyzing archive server-vmware-2016-06-20 (8/28)
Analyzing archive server-vbox-2016-06-19 (7/28)
Analyzing archive client-vmware-2016-06-19 (6/28)
Analyzing archive server-vmware-2016-06-19 (5/28)
Analyzing archive server-vbox-2016-06-18 (4/28)
Analyzing archive server-vbox-2016-06-17 (3/28)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 3894096588-3902485196)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 4142217435-4143846048)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 5142215674-5146076720)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 9025581416-9027627629)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 16676456346-16677233806)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 19461249913-19464221241)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 19831496815-19837198695)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 21796656876-21798055754)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 25209411354-25211283496)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 34240920044-34242226990)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 34895070800-34895679826)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 40756138824-40759447757)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 42145805194-42149374491)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 42332904931-42335015679)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 42645021918-42647206261)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 43472741718-43475303611)
var/lib/virtualbox/w2k8vserver/w2k8vserver.vdi: Missing file chunk detected (Byte 44357472713-44360119382)
Analyzing archive server-vbox-2016-06-12 (2/28)
Analyzing archive server-vbox-2016-06-03 (1/28)
31 orphaned objects found!
Archive consistency check complete, problems found.

Guess, server-vbox-2016-06-17 is the culprit. Hopefully, repair detects and
and eliminates the damaged archive (and the orphaned objects, while at it).

> >> How can I recover without endangering my data?
> 
> if there is a problem and the repo is valuable, make a copy of it before
> running borg check --repair on it.

I'm trusting borg and you so far. Doing the repair right now without backups.

> In this special case, the failing operation that caused the traceback is
> not the big problem - it wanted to delete something that was already gone.
> 
> But a chunk reference counter (from chunk index) disagreeing with repo
> state is the real problem here.

borg should detect this and bail out gracefully, but let's see, if it gets
this repo into a clean state again, first.

Pete