Full system backup hangs at 100% and makes the whole system very unresponsive - BackendException: Got status code 400

[papukaija]

I haven't been able to make full system backups since upgrading to Precise. The incremental backups have worked but but the full backups hang at 100% and makes the whole system very unresponsive. Even moving the mouse doesn't move the pointer on the screen. The only way to continue is to wait for ages, the pointer move very little and finally the system becomes responsive for a while before it hangs again. Then I could wait again or just use REISUB to reboot.

I first thought that Deja-dup would be uploading a very big file to U1 service but the last file in the upload file list is about 400kb in size so it isn't an upload issue. I have configured Deja-dup to backup my home folder to U1 weekly with at least 2 months for storing old backups. My U1 storage is currently at 85%.

Traceback (from deja-dup_full2.log):
DUPLICITY: WARNING 1
DUPLICITY: . Attempt 1 failed: BackendException: Got status code 400

DUPLICITY: DEBUG 1
DUPLICITY: . Backtrace of previous error: Traceback (innermost last):
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/backend.py", line 311, in iterate
DUPLICITY: . return fn(*args, **kwargs)
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/backends/u1backend.py", line 188, in put
DUPLICITY: . self.handle_error(raise_errors, 'put', answer, source_path.name, remote_full)
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/backends/u1backend.py", line 154, in handle_error
DUPLICITY: . raise BackendException(msg)
DUPLICITY: . BackendException: Got status code 400

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: deja-dup 22.0-0ubuntu1
ProcVersionSignature: Ubuntu 3.2.0-21.34-generic 3.2.13
Uname: Linux 3.2.0-21-generic i686
ApportVersion: 2.0-0ubuntu2
Architecture: i386
Date: Mon Apr 2 16:31:44 2012
EcryptfsInUse: Yes
InstallationMedia: Ubuntu-Netbook-Remix 9.10 "Karmic Koala" - Release i386 (20091028.4)
SourcePackage: deja-dup
UpgradeStatus: Upgraded to precise on 2012-03-02 (30 days ago)

[Michael Terry (mterry)]

Sorry deja-dup's causing problems for you! Can upload /tmp/deja-dup.log after running the following line and reproducing the problem?

DEJA_DUP_DEBUG=1 deja-dup --backup | tail -n 1000 > /tmp/deja-dup.log

[papukaija (papukaija)]

Thanks for the quick reply. I've attached the last 35 lines of the log to this bug. The first 965 lines have only debug 1 and info 4 messages (but I can attach the ful log if you really need it) .

As you can see from the log, deja-dup has tried to access /home/lost+found , /lost+found and even /root. None of these folders is in my backup list as it should be only backing up my own home folder. The /home/ folder is on a separate partition and my own home folder is also encrypted with ecryptfs.

Some further debugging information while running the above requested command:
The Gnome system monitor showed that the CPU usage was constantly above 50% after the backup arrived to 100%. Duplicity's memory usage grew to 650Mb in 5 mins. The system load went up to 4,5/2,8/1,5. I was away from my laptop for around 20 minutes. When I returned, the CPU usasge and sytem load were much lower but Duplicity was still using over 620Mb of momory.

I also noticed that the system didn't actually freeze completely, it's only the touchpad which stopped working and the pointer disappeared at some moment as well, but the keyboard was working. The memory usage fell back to normal after closing deja-dup with the "Continue later" option.

[Michael Terry (mterry)]

Ken, this sounds like maybe a duplicity bug. Have you seen reports like it?

[Kenneth Loafman (kenneth-loafman)]

Yes, it does.

papukaija, could you post the entire log? It would help.

[Michael Terry (mterry)]

papukaija, you might want to drop the "| tail -n 1000" bit then, though the log will be very large.

[papukaija (papukaija)]

Here's the full log.

[papukaija (papukaija)]

Oops. Didn't see the above comment while I was uploading the above file. I'll upload one without the tail option soon.

[papukaija (papukaija)]

Here's the full log. You'll notice from the log's start that duplicity crashed few times. There's also a backtrace at the end of file.

The CPU usage was again very high, between 60 and 80% during file scanning and around 20% during upload but it went above 50% when the system started to hang.

The backup process arrived to 100% in about 5 mins (but the dialog still showed the buttons to cancel/continue later) but the memory usage exploded only after 8 mins. The total system memory usage after 16 mins was at 910/991Mb. Few minutes later, duplicity's own memory usage fell a bit and the swapping reduced the usage to ~ 500Mb but then suddenly the memory usage started to grow again but I closed deja-dup before the system hanged again.

All times are from the start of the backup process.

[Kenneth Loafman (kenneth-loafman)]

You mentioned swapping... that alone will cause high CPU load.

How much memory is available on the machine?

How much memory is available to duplicity?

If you look at a process listing in tree form, does duplicity have a bunch (more than 3) of processes running?

The duplicity command line shows that it's starting at '/'. Without excludes for /proc and /dev, duplicity could have issues when scanning those directories. Also, you will need to --exclude=**/.gvfs since it violates basic access rules.

[papukaija (papukaija)]

My system has 1Gb of memory and the current memory usage without Firefox and other running applications is at 320Mb. That gives up to 670Mb for duplicity and it was using around 590Mb of memory in the last test leaving 80Mb of free system momery. I guess duplicity would have used more memory if my sytem had more memory.

I consider the swapping normal in this case as otherwise duplicity would have used all the free memory in my system. The heavy swapping started when duplicity's memory usage started to grow very quickly.

The sytem monitor didn't update instantly when my system started to hang but there was definitely only one duplicity process running before it.

As for the exclusions, Deja Dup's manual states that both ~/.gvfs and /proc are in the default exlclusion list. Shouldn't duplicity be using that list by default in addition to user defined exclusions? The /dev isn't mentioned in the manual but it shoulnd't be an issue since I've configured Deja Dup to only back up my own home folder.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Morlok8k (aoa-supercool)]

 i have a similar situation. deja-dup-monitor will suck up 630MB of RAM, and i have backups disabled! (i forget how much CPU it uses, but it's not the 100% like the above person.)

I just kill it whenever my system starts to get unresponsive, as i dont use backups. I do my own manual backups when i want to.

I have 4GB of ram, core 2 duo, 64Bit ubuntu 12.04.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[papukaija (papukaija)]

I added Ubuntu's duplicity task as the error message comes from it.

[Pierre.Bornancin (pierre-bornancin-gmail)]

I am exactly in the same situation as Morlok8k.
Although I have no backups enabled , deja-dup-monitor process takes regularly 50-60% of my cpu usage and I am forced to kill it as soon as my system gets unresponsive.

[papukaija (papukaija)]

I added the regression tag since this didn't occur in Oneiric.

[papukaija (papukaija)]

The issue with the file folder exclusions (comments 10 and 11 above) is confirmed by bug 1013207.

[Michael Terry (mterry)]

I'm going to close out this bug.

Some of the mentioned issues have other bugs (deja-dup-monitor taking resources is bug 1302416). And the main report of a backup error of "Got status code 400" is for the U1 backend, which is defunct now that U1 shut down.