Show appropriate error message if duplicity runs out of memory

[Kevin Zollman]

I am doing a dry-run of restoring from a backup on google drive. I started a clean virtual machine installed with Ubuntu and Deja Dup. I got it authorized with my google account and started a restore. It asks for the location, finds the backup and asks for a date to restore, asks for a location to restore to, and asks for a password. After I enter the password, it continues with the "Restoring. Preparing.." screen for a long while. Then it appears to crash. It simply returns to the window that opens when I start Deja Dup without having restored anything or giving any error message.

I ran it with debug turned on, and I've attached the output of that. There is no obvious error message there that I can see in that file.

Both backups and restore are on:

OS: Ubuntu 20.04
Deja-Dup: 40.6-1ubuntu2
Duplicity: 0.8.11.1612-1

The restore is running in a virtual machine (VirtualBox) that I created on the backup machine for the sole purpose of testing the restore. It is a clean (minimal) install of Ubuntu 20.04.

Here's the output of gsettings on the virtual machine (restore):

org.gnome.DejaDup exclude-list ['$TRASH', '$DOWNLOAD']
org.gnome.DejaDup allow-metered false
org.gnome.DejaDup root-prompt true
org.gnome.DejaDup periodic-period 7
org.gnome.DejaDup include-list ['$HOME']
org.gnome.DejaDup prompt-check '2020-06-10T19:22:59+00'
org.gnome.DejaDup periodic false
org.gnome.DejaDup delete-after 0
org.gnome.DejaDup last-restore ''
org.gnome.DejaDup last-run ''
org.gnome.DejaDup full-backup-period 90
org.gnome.DejaDup last-backup ''
org.gnome.DejaDup backend 'google'
org.gnome.DejaDup nag-check ''
org.gnome.DejaDup.S3 folder 'virtualHamilton'
org.gnome.DejaDup.S3 bucket ''
org.gnome.DejaDup.S3 id ''
org.gnome.DejaDup.Rackspace container 'virtualHamilton'
org.gnome.DejaDup.Rackspace username ''
org.gnome.DejaDup.OpenStack authurl ''
org.gnome.DejaDup.OpenStack tenant ''
org.gnome.DejaDup.OpenStack container 'virtualHamilton'
org.gnome.DejaDup.OpenStack username ''
org.gnome.DejaDup.GCS folder 'virtualHamilton'
org.gnome.DejaDup.GCS bucket ''
org.gnome.DejaDup.GCS id ''
org.gnome.DejaDup.Local folder 'virtualHamilton'
org.gnome.DejaDup.Google folder 'virtualHamilton'
org.gnome.DejaDup.GOA folder '$HOSTNAME'
org.gnome.DejaDup.GOA id ''
org.gnome.DejaDup.GOA type ''
org.gnome.DejaDup.GOA migrated false
org.gnome.DejaDup.Drive folder '$HOSTNAME'
org.gnome.DejaDup.Drive uuid ''
org.gnome.DejaDup.Drive name ''
org.gnome.DejaDup.Drive icon ''
org.gnome.DejaDup.File path ''
org.gnome.DejaDup.File relpath @ay []
org.gnome.DejaDup.File name ''
org.gnome.DejaDup.File migrated true
org.gnome.DejaDup.File type 'normal'
org.gnome.DejaDup.File uuid ''
org.gnome.DejaDup.File short-name ''
org.gnome.DejaDup.File icon ''
org.gnome.DejaDup.Remote folder 'virtualHamilton'
org.gnome.DejaDup.Remote uri ''

[Michael Terry (mterry)]

That sounds very frustrating! I'm sorry this bug is hitting you.

This doesn't sound familiar to me. And you're right that that log isn't very useful... And it doesn't sound like Deja Dup is actually crashing-crashing, which would at least let us know where the problem is.

I'm not sure what the next step to debug this would be...

You were just doing a dry run yeah? So you don't need emergency measures like using duplicity directly on the command line.

Oh! I've got an idea. There is support for using policykit to elevate Deja Dup to root privileges for a restore, if we think we are restoring something outside of HOME. This can (A) sometimes prompt if it doesn't *really* need to -- like a file is outside HOME but can still be written to and (B) doesn't have great fallback code if policykit isn't functioning. (which might be as dumb as simply aborting the restore without a message?)

It *might* be hitting that (B) scenario on a VM maybe? There is an easy way to test by instead of restoring files to their original locations (which might be outside HOME) and instead restore to a file of your choosing inside your HOME.

Try that and let me know?

I'm actively (as I type this!) in the middle of working on a replacement system that will avoid using policykit.

[Kevin Zollman (kzollman)]

Thank you for your prompt reply. If I understand correctly, I think I was already doing what you requested. The backup was of my home directory "/home/kzollman" and the dry run was being done to "/home/kzollman/restore test" For completeness I also tried restoring it to the original location (which would be /home/kzollman) and got the same result. I double checked and I have permission to write to "/home/kzollman/restore test".

Poking around in the logs, it seems to be breaking while executing the list-current-files part of the restore. I don't know if this helps or not (perhaps that was already obvious from the logs).

Would it make sense to test it as root? Or is that a bad idea?

[Michael Terry (mterry)]

> Would it make sense to test it as root? Or is that a bad idea?

Maybe? It's not generally a recommended path (Deja Dup does a lot of talking to your session dbus and that doesn't work as well when run as root).

"list-current-files" is the thing it does right before it starts really restoring (rather than just prepping and sussing out your backup files). Not sure that's a helpful hint.

(That does match up with my worry about policykit. But as you say, that shouldn't be involved based on how you're restoring.)

I have not run Deja Dup in a VM in a while. I wonder if there's something we do that would be incompatible in that setting?

[Kevin Zollman (kzollman)]

Some brief updates. I tried running it as root in the VM, and that didn't work. It seemed to have trouble getting the keys for the google drive. I'll admit I didn't try terribly hard to solve this particular problem. (PS There is a small bug in how google is authorized for restores, I'll submit that as a second bug report.)

Second, I tried a test restore on the backup machine (NOT the VM) and it seemed to work fine. I didn't do a complete restore, but got it started and it made it past where it was dying on the VM.

So, this seems to suggest that there maybe something with the VM causing the problem, although I suppose it doesn't demonstrate it conclusively. Perhaps someone else could try a test with a VM and see if that's a problem. I am using VirtualBox 6.1.6_Ubuntu r137129 out of the box (sorry for the pun), nothing special or fancy. I tried it both with Ubuntu 20.04 "minimal" and "normal" installs, and both had this problem.

[Michael Terry (mterry)]

OK, I'll test with a VM and see if I can reproduce.

[Michael Terry (mterry)]

Hmm. I was not able to reproduce. Same version of VirtualBox (6.1.6_Ubuntu r137129). Ubuntu 20.04. Deja Dup 40.6-1ubuntu2.

I tried an encrypted and unencrypted restore. Tried restoring to original locations and to new. Tried local and Google storage locations.

Makes me wonder what the difference between our attempts is.

[Kevin Zollman (kzollman)]

Sorry if this is tedious, but I thought it worth putting together all the data points in one place. I've included two new ones at the end.

Just to keep things clear, here's the terminology I'm using.

Original Machine: This is the computer that created the original large backup which is under discussion.

VM: This a virtual machine running on Original Machine.

Junky Machine: This is a computer I pulled out of the closet to test what's going on. It's running Ubuntu 18.04.3 LTS, Deja Dup 40.7 via snap.

(Old) Data point #1. (This is the original bug.) Backup made on Original Machine would cause the aforementioned crash when I attempted to restore on the VM.

(Old) Data point #2. Same backup made on Original Machine would appear to restore correctly on Original Machine.

(New) Data Point #3. To make sure the problem wasn't in my VM, I created a very small backup from the VM, performed it, and then restored it to the VM. That worked fine, no crash.

(New) Data Point #4. I pulled out Junky Machine from the closet and attempted to perform a restore on my original backup. Boy did it take a while, but it eventually got past where the VM was crashing. I let it restore a few files to make sure it was working and then canceled.

At this point, my best guess is that it's something about my particular backup AND the VM. Could it be the size of the backup is interacting with the VM? It's a very large backup. (~350GB)

Can I do anything else, or give you any additional information that would help you track this down? Obviously, on my end it's not critical. The backup appears to have worked and I seem to have several options for restoring. But, *something* isn't working correctly, somewhere...

[Michael Terry (mterry)]

One thought... Deja Dup is quite greedy in terms of metadata cache files and your hard drive space. With a large backup, maybe we're taking too much cache space in your VM and we run out of space in a way we don't expect?

Possibly we do some cache cleanup after the failure so you may not notice after the restore fails. Best bet would be to monitor while Deja is doing work.

[Kevin Zollman (kzollman)]

Aha! It's memory. There is no appreciable change to hard disk usage during the failure, but while it is "adding to cache" the .sigtar.gpg file, it fills up resident memory. That file is ~2gb on google drive and I only allocated 2gb of memory to the virtual machine.

While deja-dup/duplicity is adding it to the cache, the resident memory being used by the duplicity process grows to well over 1.5gb. Available memory and swap drops to zero. (By the way, the temporary file it claims to be creating never shows up.) The duplicity process then disappears and this is when the restore stops. So it must be that the duplicity process is crashing because of lack of memory.

To test that this was the culprit I tried increasing the memory available to the virtual machine to 4gb and 6gb and tried the restore again. This remained too small, and the same original bug behavior was observed. But increasing the memory to 8gb did the trick! It failed a little later because the HD was also too small, but it failed with an error message explaining that problem.

This is obviously not a serious bug for me. But it does seem like there should be an error message indicating that memory is a problem rather than quietly failing.