deja-dup (or duplicity) deletes all signatures

[emilio]

This is a follow up from bug 403790.

The fix solved the problem with the non gizipped manifests. However the original error is still there:

I summarize below the problem:
-After a full backup and few incremental ones deja-dup returned "Unknown error"
-After the exception I run again deja dup and after "Preparing" message a "Cleaning" message appeared and deja-dup started a new full backup
-After the full backup all the signature files from the old backups have disappeared from the share and cache (Is this due to the cleaning step?). In fact deja-dup does not display any of these old restore points in the in the restore window.

May be the last backup was corrupted and duplicity failed. However is it necessary to delete all the signature files? Should duplicity delete just the last incremental backup and try again from the one before?

Duplicity 0.6.03
deja-dup 10.1

[Michael Terry (mterry)]

Thanks emilio for the bug report! :)

If you're able to reproduce the 'Unknown Error' message, is there a stacktrace shown?

So, Ken, an explanation of how deja-dup cleans up may be in order. If we get any of the following warnings from duplicity:
      case WARNING_ORPHANED_SIG:
      case WARNING_UNNECESSARY_SIG:
      case WARNING_UNMATCHED_SIG:
      case WARNING_INCOMPLETE_BACKUP:
      case WARNING_ORPHANED_BACKUP:
or the user cancels a backup, deja-dup starts a cleanup operation.

It sounds like the cleanup is deleting more files than it should?

[emilio (emiliomaggio)]

Sorry no stacktrace. Is deja-dup logging information somewhere?

On Thu, 2009-08-06 at 07:51 +0000, Michael Terry wrote:
> Thanks emilio for the bug report! :)
>
> If you're able to reproduce the 'Unknown Error' message, is there a
> stacktrace shown?
>
> So, Ken, an explanation of how deja-dup cleans up may be in order. If we get any of the following warnings from duplicity:
> case WARNING_ORPHANED_SIG:
> case WARNING_UNNECESSARY_SIG:
> case WARNING_UNMATCHED_SIG:
> case WARNING_INCOMPLETE_BACKUP:
> case WARNING_ORPHANED_BACKUP:
> or the user cancels a backup, deja-dup starts a cleanup operation.
>
> It sounds like the cleanup is deleting more files than it should?
>
> ** Changed in: deja-dup
> Importance: Undecided => Critical
>

[Michael Terry (mterry)]

I thought deja-dup 10.1 showed you a stacktrace when it gave the 'unknown error' message. But there are probably cases where it doesn't.

You can make deja-dup log info with something like the following command:
    DEJA_DUP_DEBUG=1 deja-dup | tail -n 200 > /tmp/deja-dup.log

[emilio (emiliomaggio)]

The problem happened again. This time as I unplagged my laptop power supply.

Here is some extra info:

-After the error the signature files are gone (so it is not the clean-up operation of the next backup)

-If I try a restore with deja-dup I get this error:
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1241, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1234, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1139, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 675, in set_values
    backup_chains = self.get_sorted_chains(backup_chains)
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 932, in get_sorted_chains
    assert chain_list[1].archive_dir # other is local
AttributeError: BackupChain instance has no attribute 'archive_dir'

-This is the content of ".cache/deja-dup":

./85c40e0ebdf5c6707e19fe14a62a31f0:
duplicity-full.20090726T100318Z.manifest
duplicity-full.20090801T232121Z.manifest
duplicity-full.20090808T105947Z.manifest.part
duplicity-full-signatures.20090808T105947Z.sigtar.part
duplicity-inc.20090726T100318Z.to.20090726T160902Z.manifest
duplicity-inc.20090726T160902Z.to.20090726T163151Z.manifest
duplicity-inc.20090801T232121Z.to.20090802T005412Z.manifest
duplicity-inc.20090802T005412Z.to.20090805T184646Z.manifest
duplicity-inc.20090805T184646Z.to.20090805T230029Z.manifest
duplicity-inc.20090805T230029Z.to.20090806T220754Z.manifest
duplicity-inc.20090806T220754Z.to.20090807T182904Z.manifest
duplicity-inc.20090807T182904Z.to.20090808T105947Z.manifest.part
duplicity-new-signatures.20090807T182904Z.to.20090808T105947Z.sigtar.part

-The list of the content of the backup folder, after the error is attached (note that the failed backup was a full backup.... why deja-dup started a full backup? May be the problem was with the previous incremental backup?)

[emilio (emiliomaggio)]

This is the log if I try a backup with the command
DEJA_DUP_DEBUG=1 deja-dup-applet | tail -n 200 > /tmp/deja-dup.log

[emilio (emiliomaggio)]

I have just reproduced the bug, with the following steps:

1)Perform one full backup
2)Perform a few incremental backups shuffling some files
3)During one of the incremental backups disable the network connection. Deja-dup (as it should) fails, but the signature files are still in the backup folder
4)Reenable the network connection and start a new backup.

The 4th step results in deja-dup deleting all the signatures and starting a new full backup that also failed. However the last time the back up did not fail.
A weird note.... the volume numbering of this full backup does not start from 1 but form continues the numbering of the last incremental backup, the one interrupted during step 3.

I log file from step 4 is attached.

[Kenneth Loafman (kenneth-loafman)]

If I understand it, then the commands duplicity receives in this case would be:

full
inc
inc
inc...fail
cleanup
inc

Is that correct?

[emilio (emiliomaggio)]

Almost... the last one is a full. After failing duplicity deletes all the signatures and seems to be unaware of any previous backup.

[emilio (emiliomaggio)]

Sorry I have answered too quickly. For the last command I have seen both cases incremental and full.

When I managed to reproduce the bug the deja-dup started an incremental backup.

[Michael Terry (mterry)]

Ken, the commands would all be implicit no-commands which are 'inc'. Deja Dup wouldn't send an explicit full.

[Kenneth Loafman (kenneth-loafman)]

Michael Terry wrote:
> Ken, the commands would all be implicit no-commands which are 'inc'.
> Deja Dup wouldn't send an explicit full.

This is a problem with running cleanup after a partial backup since
duplicity is expecting to go into the restart process and Deja Dup is
telling it to do a cleanup, which is the wrong thing to do at this
point. What would you need from duplicity to let Deja know that a
cleanup is not the desired activity at this point?

Kind os a Catch-22... if we clean up, we lose the partial backup and the
time it took to make, but if we force restart of the partial we may fail
because the cleanup would have cleared enough space for us to run.

As much as I dislike the solution, the only way to go at this point
seems to be to clean off the partial backup and restart duplicity with
the cleanup command. That will work, but throws away all the previous
work done in the partial.

[Michael Terry (mterry)]

Ken, yeah, Deja Dup still hasn't been designed to work amazingly with duplicity's restarting. I plan to flesh that support out for version 11.

But Deja Dup only cleans up if the user cancels the backup (or duplicity tells us there's extra files when we start -- which it might do about partial backups?).

In any case, I hope that a cleanup of a partial backup would not delete signatures needed to access the rest of your backups.

[Kenneth Loafman (kenneth-loafman)]

If there is a partial backup in place when cleanup is run, the assumption is that the user wants to remove that as well as do the cleanup. This does exactly that. I also added a cleanuptest.py unittest module with this bug as a regression test. Now cleanup will not get confused and delete the signature files.

[Michael Terry (mterry)]

Hot. That sounds like what I'd expect. I just have to fix Deja Dup to not be so cleanup-happy.