Backup to Ubuntu one failed, after 5 attempts status 400 bad request

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

I've been having this problem in Raring for a few months now. I started doing some investigating and tried running the same duplicity command that deja-dup spawns. When I do that, duplicity asks for my Ubuntu One email address and then password. I'm beginning to think that deja-dup is not handling this input correctly.

So after using the duplicity command line mentioned above and then killing that backup and then running a backup through deja dup, it is working so far now. It hasn't completed the backup yet, but it has gotten farther than it had in quite some time.

Bah, it failed:(

I'm going to let the duplicity backup run and see if it fails anywhere along the way.

Well, the duplicity only command failed as well with the "400 Bad Request" error, so this seems to either be a problem in duplicity or how Ubuntu One is handling something. It seems to prompted by a read operation timeout.

Here is the snippet of duplicity output with the failure:
uploading file duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz to location https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz
Level 5:duplicity:uploading file duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz to location https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz
making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 1)
Level 5:duplicity:making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 1)
request failed, exception The read operation timed out
Level 5:duplicity:request failed, exception The read operation timed out
making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 2)
Level 5:duplicity:making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 2)
completed request with status 400 Bad Request
Level 5:duplicity:completed request with status 400 Bad Request
making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 3)
Level 5:duplicity:making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 3)
completed request with status 400 Bad Request
Level 5:duplicity:completed request with status 400 Bad Request
making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 4)
Level 5:duplicity:making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 4)
completed request with status 400 Bad Request
Level 5:duplicity:completed request with status 400 Bad Request
making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 5)
Level 5:duplicity:making PUT request to https://files.one.ubuntu.com/content/~/deja-dup/Falcon/duplicity-inc.20130301T000911Z.to.20130415T174047Z.vol8.difftar.gz (attempt 5)
completed request with status 400 Bad Request
Level 5:duplicity:completed request with status 400 Bad Request
Giving up on request after 5 attempts, last status 400 Bad Request
DEBUG:duplicity:Giving up on request after 5 attempts, last status 400 Bad Request

I upped the verbosity of the duplicity command, and here is the Python backtrace of the read operation timeout:

Level 1:duplicity:Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib/python2.7/dist-packages/duplicity/backends/u1backend.py", line 80, in request
    resp, content = self.client.request(url, method, headers=headers, body=body)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1596, in request
    (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1344, in _request
    (response, content) = self._conn_request(conn, request_uri, method, body, headers)
  File "/usr/lib/python2.7/dist-packages/httplib2/__init__.py", line 1314, in _conn_request
    response = conn.getresponse()
  File "/usr/lib/python2.7/httplib.py", line 1045, in getresponse
    response.begin()
  File "/usr/lib/python2.7/httplib.py", line 409, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python2.7/httplib.py", line 365, in _read_status
    line = self.fp.readline(_MAXLINE + 1)
  File "/usr/lib/python2.7/socket.py", line 476, in readline
    data = self._sock.recv(self._rbufsize)
  File "/usr/lib/python2.7/ssl.py", line 298, in recv
    return self.read(buflen)
  File "/usr/lib/python2.7/ssl.py", line 217, in read
    return self._sslobj.read(len)
 SSLError: The read operation timed out

After doing some research, it appears that when an "SSLError: The read operation timed out" occurs, the connection is closed. In the code that handles this, there is a retry loop, but the retry loop does not re-set up the connection, so I believe this is the source of the "Bad Request". It's not clear why there is a read time out in the first place, but perhaps a way to workaround this is to add code in the loop to re-set up the connection when this error is seen.

I'm quite convinced this issue is not anything in Deja Dup, so I'm setting that bug invalid.

I'm still not really sure what the real issue is. I've done quite a bit of experimentation and still unable to pin this on duplicity, ssl, or even the Ubuntu One server. I have gathered a Wireshark trace and I'm trying to sift through the capture to see if gives any clues on what this may be.

I think there are two issues going on here.

The first issue that occurs during or right after a file is uploaded. The python httplib code does a call to get a response from the server for the packet sent. It appears there may be a transient error such a socket timeout or something up with the response header. When this error occurs, the httlib2 code then does a retry of the original PUT. This is where the second issue occurs.

When this occurs, we always get back a '400 Bad Request' error from the server. It is not clear to me why this error occurs since the same exact PUT is used from the first try. Will probably need to ask someone from the Ubuntu One team why the server thinks the second (and subsequent) retries are malformed when the server doesn't think the first one is.

It is interesting that I have never seen the problem on 12.04. That suggests that it is not just a problem on the Ubuntu One server, unless the error recovery in httlib2 has changed in a way that triggers the problem on the server. Or perhaps the initial error is caused by a bug in the client (or just a change in the way it works) so that although in theory the problem could occur on 12.04 it was in practice not seen.

Hi Colin,

I started noticing this issue on 13.04 around the beginning to middle of March or so. I have not tried this on 12.04 in some time. Are you able to do a backup to U1 with 12.04 recently?

What is strange that a retry of the same PUT request gets the '400 Bad Request' error every time. This suggests that the U1 server doesn't like *something* about that request. I'd really like to know what it doesn't like about it, so maybe we can workaround the transient issue by actually re-sending the PUT request in a manner that the server likes.

Hi Christopher
I use it on two machines, one running 12.04 and one 13.04 and have only seen it on 13.04. I was not using it on 13.04 prior to 28 March when I reported this bug so I don't know whether it was present in 13.04 prior to that date.

Hi Colin,

Thanks! Knowing that 12.04 works today is a good data point.

I'm working with the U1 folks to help diagnose this. Hopefully they can help shed some light on this.

We've managed to rule out an application error. Those '400 Bad Request' are being returned by Apache, so we have great confidence than somehow a malformed request is being sent, which Apache then rejects.

Here's a breakdown of Status 400 failures from the Apache logs over the course of ~24h:

Python-httplib2/0.7.0 5
Python-httplib2/0.7.2 617
Python-httplib2/0.7.4 393
Python-httplib2/0.7.6 1
Python-httplib2/0.7.7 596
Python-httplib2/0.8 7

From https://launchpad.net/ubuntu/+source/python-httplib2 we can see that 0.7.2 is Precise/Oneiric and 0.7.4 is Quantal, 0.7.7 being Raring and 0.7.0/0.8 probably some people with a package from a PPA.

Looking at the way that httplib2 catches exceptions, if there's for example a socket.timeout the conn object is not closed (https://code.google.com/p/httplib2/source/browse/python2/httplib2/__init__.py#1257) I suspect that might leave the conn object in a semi-broken state.

Since duplicity instantiates an httplib2 Http object and keeps it around (http://bazaar.launchpad.net/~duplicity-team/duplicity/0.6-series/view/head:/duplicity/backends/u1backend.py#L51), not creating a new one in the case of exceptions (http://bazaar.launchpad.net/~duplicity-team/duplicity/0.6-series/view/head:/duplicity/backends/u1backend.py#L80) I suspect that means a broken connection will be used on timeouts. A simple fix might be to throw away the Http object and create a new one.

I'm going to give that a try (since I can reproduce the issue) and report back.

Actually it might be more obvious than it seems.

When the PUT request is done, an open file handle is passed as the 'body' argument to httplib2 request(). Since there was a timeout and retry, the file handle was read from so the current position in the file has moved. There's no seek() back to the beginning of the file on retry, so Content-Length doesn't match the body that was sent anymore.

Seems like the 'body' should be seek()'d back to the beginning (or to the original position, by getting position with tell() before the request) on retry if it's a file handle.

Testing to see if this fixes the problem.

Confirmed that this fixes the problem. When rewinding the file handle on retry the subsequent PUT request *does* succeed.

Hi Sidnei,

Great work! The file pointer position crossed my mind, but the 400 Bad Request was throwing me off.

I now see the commit that broke this: http://bazaar.launchpad.net/~duplicity-team/duplicity/0.6-series/revision/901 in duplicity/backends/u1backend.py. It went from using a bytearray to using the file pointer as you mention. Of course when using the bytearray, it will begin at the front when retrying.

I also noticed that in that same commit, the Content-Length header was removed. I believe this is wrong as well based on the U1 API documentation.

My proposed fix wasn't exactly complete. Will link a new branch to fix that and submit another merge proposal.

So testing with both of my merge proposals, I will still occasionally see a '400 Bad Request' error or some other error such as a socket error or a '502 Bad Gateway'. Most of the time, the retry is successful, but on a rare occasion, I'm seeing all 5 retries fail which causes the backup to fail. I've attached a file with a snippet of the debug output of a failed backup.

This is very strange and I have no clue why the Apache server is responding in these ways. I guess this still needs more investigation.

Hi,
I'm just wondering whether there is any progress on this issue. Unfortunately, this bug makes the Ubuntu backup system unusable for the affected users, leaving them without a backup of their data. So I believe this creates a certain level of pressure of eventually fixing this. Thanks!

Hi All,

I fixed this in the Duplicity source code. The next step is to get it in the Duplicity package and get it through the Stable Release Update (SRU) process. I'm not sure what the maintainers of Duplicity plans are on when they are going to get the SRU going, but I imagine they would be getting it ready soon(ish).

For the record, I just now stumbled across this bug report after getting sick of closing deja-dup when it fails on every single boot. I am still receiving the 400 error. I'm not becoming impatient or anything, simply reporting that it is affecting another person.

Thank you all.

Try using Back In Time instead of Deja Dup. It works perfectly.

On Sun, May 12, 2013 at 4:45 PM, Jacob Mischka <email address hidden>wrote:

> For the record, I just now stumbled across this bug report after getting
> sick of closing deja-dup when it fails on every single boot. I am still
> receiving the 400 error. I'm not becoming impatient or anything, simply
> reporting that it is affecting another person.
>
> Thank you all.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1161599
>
> Title:
> Backup to Ubuntu one failed, after 5 attempts status 400 bad request
>
> Status in Déjà Dup Backup Tool:
> Invalid
> Status in Duplicity - Bandwidth Efficient Encrypted Backup:
> Fix Committed
> Status in “deja-dup” package in Ubuntu:
> Invalid
> Status in “duplicity” package in Ubuntu:
> Confirmed
>
> Bug description:
> On Raring using deja-dup to backup to Ubuntu one, when I add a
> particular git repository to the folders to backup and then start the
> backup, the process sits for some minutes at the start of the upload
> operation and then fails with a popup "Backup Failed. Giving up on request
> after 5 attempts last status 400 bad request". The progress bar does not
> get started as far as I can see.
> While it is saying that it is uploading I can see in System Monitor that
> data is being continuously sent, but after the failure there are no new
> files on U1.
>
> By a process of elimination I determined that it is the objects
> directory (which itself contains a large number of subdirectories each
> containing a number of small files) that is causing the problem. I
> attempted to determine whether it was a particular file or folder that
> was causing the problem but it seems not to be consistent. I thought
> that I had found a particular subfolder causing the problem, I cleared
> .cache/deja_dup, and then it accepted that folder. However when I
> then put back the rest of the subfolders it failed again.
>
> I copied the complete git repository to another machine (running up to
> date Ubuntu 12.04) and backing up from there (to a different U1
> account) deja_dup has no problems.
>
> I also notice that on Raring it always takes a long time in the
> verification phase even when only a trivial change has been made. It
> is as if it is downloading the whole repository, but whether that is a
> related problem I do not know.
>
> ProblemType: Bug
> DistroRelease: Ubuntu 13.04
> Package: deja-dup 25.5-0ubuntu1
> ProcVersionSignature: Ubuntu 3.8.0-15.25-generic 3.8.4
> Uname: Linux 3.8.0-15-generic i686
> ApportVersion: 2.9.2-0ubuntu5
> Architecture: i386
> Date: Thu Mar 28 20:28:06 2013
> InstallationDate: Installed on 2012-08-01 (239 days ago)
> InstallationMedia: Ubuntu 12.10 "Quantal Quetzal" - Alpha i386
> (20120730.1)
> MarkForUpload: True
> SourcePackage: deja-dup
> UpgradeStatus: No upgrade log present (probably fresh install)
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/deja-dup/+bug/1161599/+subscriptions
>

--
*JC*

If you put this file in /usr/share/pyshared/duplicity/backends/u1backend.py does it work?

I've been dragging my feet on pushing this fix to Ubuntu, sorry. I've had an unrelated problem that made testing difficult.

Michael:

This fixed the problem for me. Thanks for your work.

Christopher Townsend wrote the patch, I'm just doing the paperwork of uploading it. :)

I've uploaded to saucy and to raring. I've subscribed ubuntu-sru for the raring one.

This bug was fixed in the package duplicity - 0.6.21-0ubuntu2

---------------
duplicity (0.6.21-0ubuntu2) saucy; urgency=low

  * debian/patches/01u1backend.dpatch:
    - Backport some fixes for avoiding "400" errors when backing up to
      Ubuntu One. Patch by Christopher Townsend. LP: #1161599
 -- Michael Terry <email address hidden> Wed, 15 May 2013 16:11:24 -0400

Hello Colin, or anyone else affected,

Accepted duplicity into raring-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/duplicity/0.6.21-0ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Hello everybody,

How can I update to this version?

Thank you,

Cho

Hey Cho,
um. read the previous comment once more.
In short,
1) Goto software sources and add raring-proposed.
2) Then as per this link (https://wiki.ubuntu.com/Testing/EnableProposed) to enable only partial update from the proposed channel create a /etc/apt/preferences file with the given parameters replacing precise with raring.
3) run sudo apt-get update
4) run sudo apt-get install duplicity/raring-proposed.
5) report back your test results.

@Brian
Testing underway. Could install no probs. and duplicity is running fine. Yet to complete so that I can confirm it works. But until now the usual points where the error popped up, it's been smooth. Will reply once the current backup gets over.

Verified. My backup was done and since my backup was due for a while it even checked my existing backup. No troubles. Temme what to do if you need more info.

Can confirm that the fix works.

So I have duplicity 0.6.21-0ubuntu1.1. Now my backup finished with an unknown error:
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1411, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1404, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1338, in main
    restore(col_stats)
  File "/usr/bin/duplicity", line 632, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 526, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 499, in integrate_patch_iters
    final_ropath = patch_seq2ropath( normalize_ps( patch_seq ) )
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 463, in patch_seq2ropath
    assert first.difftype != "diff", patch_seq
AssertionError: [(('README',) reg), (('README',) reg), (('README',) reg), (('README',) reg), (('README',) reg)]

Just to add I have been getting this bug since I updated to 13.04. Just did the install from "proposed" (hope I did it right) and testing now.....
...it's also doing a restore test (I guess it's been a while)....hmmm, looks like I forgot my password....ok, got the password, but it seems to not be moving forward....still says verifying backup....

OK I got a pop up message saying "not all your files were backed up, please see log for details" but that went away and the main window of the backup app says "Backup Finished/Your files were successfully backed up and tested//home/kibi/.local/share/recently-used.xbel"
That last is just an xml looking file with some recently used apps - not sure what that means

So, in short, I think it's working but I'm not 100% sure. in the main Duplicity window it says my latest backup was today which is a good thing I think.

Having tested, can I remove "proposed" from my sources, or will this cause a revert?

The verification of this Stable Release Update has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regresssions.

This bug was fixed in the package duplicity - 0.6.21-0ubuntu1.1

---------------
duplicity (0.6.21-0ubuntu1.1) raring; urgency=low

  * debian/patches/01u1backend.dpatch:
    - Backport some fixes for avoiding "400" errors when backing up to
      Ubuntu One. Patch by Christopher Townsend. LP: #1161599
 -- Michael Terry <email address hidden> Wed, 15 May 2013 16:11:24 -0400

I have the exact error described in this bug description even with this fix included in duplicity.

I am using 13.10 with duplicity 0.6.21-0ubuntu4.1.

Is anyone else still experiencing this error?

I have the same symptoms, after upgrading (downgrading?) from 12.04 to 13.10. My deja-dup backups to Ubuntu One are failing after 10 to 15 minutes, with the "after 5 attempts" disconnect message. This is really annoying after it worked fine under 12.04. (3.11.0-17-generic #31-Ubuntu SMP Mon Feb 3 21:52:43 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux)

As I cannot reopen this issue (which properly does not make sense anyway) have I opened a new Bug #1294201 which explains the issue again how I still experience it even with duplicity including bug fix provided for this issue.