B2 always fails (hung) with 0.7.15

[Rick Gabriel]

Duplicity 0.7.15 consistently fails to backup to my B2. I think it might only affect large, full backups with multiple volumes. Some time after the upload of the first volume is underway, the duplicity process will begin using 100% CPU. strace reveals one of the following, depending on whether duplicity is run in async or sync mode:

ASYNC: futex(0x1367b10, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff
SYNC: select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)

Duplicity 0.7.14 seems to work normally. Unfortunately, no errors nor unusual messages are reported in the log, even with verbosity 9. The application just hangs in an infinite loop until manually killed. Small, incremental backups seem to succeed.

One duplicity command that always hangs is below. The problem also occurs without the --full-if-older-than and --volsize parameters.

duplicity --name duply_photography --encrypt-key XXX --sign-key XXX --verbosity 9 --gpg-options --compress-algo=bzip2 --bzip2-compress-level=9 --personal-cipher-preferences AES256,AES192 --full-if-older-than 1Y --volsize 500 --exclude-filelist /root/.duply/photography/exclude / b2://xxx@xxx/photography

[Kenneth Loafman (kenneth-loafman)]

@speedy37 -- Any idea what's going on here?

[Rick Gabriel (klaxian1)]

If it helps, here are the versions of python and b2-related packages installed on my system:

python: 2.7.12

Name: b2
Version: 1.0.0
Summary: Command Line Tool for Backblaze B2
Home-page: https://github.com/Backblaze/B2_Command_Line_Tool
Author: Backblaze, Inc.
Author-email: <email address hidden>
License: MIT
Location: /usr/local/lib/python2.7/dist-packages
Requires: arrow, futures, logfury, requests, six, tqdm
---
Name: arrow
Version: 0.10.0
Summary: Better dates and times for Python
Home-page: https://github.com/crsmithdev/arrow/
Author: Chris Smith
Author-email: <email address hidden>
License: Apache 2.0
Location: /usr/local/lib/python2.7/dist-packages
Requires: python-dateutil
---
Name: futures
Version: 3.1.1
Summary: Backport of the concurrent.futures package from Python 3.2
Home-page: https://github.com/agronholm/pythonfutures
Author: Alex Gronholm
Author-email: <email address hidden>
License: PSF
Location: /usr/local/lib/python2.7/dist-packages
Requires:
---
Name: logfury
Version: 0.1.2
Summary: Toolkit for responsible, low-boilerplate logging of library method calls
Home-page: https://github.com/ppolewicz/logfury
Author: Pawel Polewicz
Author-email: <email address hidden>
License: BSD
Location: /usr/local/lib/python2.7/dist-packages
Requires: six, funcsigs
---
Name: requests
Version: 2.18.1
Summary: Python HTTP for Humans.
Home-page: http://python-requests.org
Author: Kenneth Reitz
Author-email: <email address hidden>
License: Apache 2.0
Location: /usr/lib/python2.7/dist-packages
Requires:
---
Name: six
Version: 1.11.0
Summary: Python 2 and 3 compatibility utilities
Home-page: http://pypi.python.org/pypi/six/
Author: Benjamin Peterson
Author-email: <email address hidden>
License: MIT
Location: /usr/lib/python2.7/dist-packages
Requires:
---
Name: tqdm
Version: 4.19.4
Summary: Fast, Extensible Progress Meter
Home-page: https://github.com/tqdm/tqdm
Author: tqdm developers
Author-email: <email address hidden>
License: MPLv2.0, MIT Licences
Location: /usr/local/lib/python2.7/dist-packages
Requires:

[Vincent Rouille (speedy37)]

No idea, I'm using my new B2 backend since a year now on about 500GB of data, no issue.

[Rick Gabriel (klaxian1)]

Try running a full backup with multiple volumes? B2 works fine for me with duplicity 0.7.14, but it fails for large backups after I upgrade to 0.7.15.

[Kenneth Loafman (kenneth-loafman)]

OK, let's see what's going on... I need some info:

1) the v9 log file (first 200 lines, last 200 lines)
2) OS and version.
3) memory available for duplicity

[Vincent Rouille (speedy37)]

full each month with about one hundred volumes of 1GB. I'm using https://hub.docker.com/r/speedy37/docker-duplicity/ (v0.7.11 with the new B2 backend).

I will try a full backup directly with 0.7.15 once I find a moment to upgrade my docker image.

[Vincent Rouille (speedy37)]

Also my b2 package version is older 0.7.0

[Kenneth Loafman (kenneth-loafman)]

Try installing B2 version 0.7.0 to see if it works, "pip install -U
b2==0.7.0".

On Wed, Nov 15, 2017 at 9:14 AM, Vincent Rouille <<email address hidden>
> wrote:

> Also my b2 package version is older 0.7.0
>
> --
> You received this bug notification because you are subscribed to
> Duplicity.
> https://bugs.launchpad.net/bugs/1732269
>
> Title:
> B2 always fails (hung) with 0.7.15
>
> Status in Duplicity:
> New
>
> Bug description:
> Duplicity 0.7.15 consistently fails to backup to my B2. I think it
> might only affect large, full backups with multiple volumes. Some time
> after the upload of the first volume is underway, the duplicity
> process will begin using 100% CPU. strace reveals one of the
> following, depending on whether duplicity is run in async or sync
> mode:
>
> ASYNC: futex(0x1367b10, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME,
> 0, NULL, ffffffff
> SYNC: select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>
> Duplicity 0.7.14 seems to work normally. Unfortunately, no errors nor
> unusual messages are reported in the log, even with verbosity 9. The
> application just hangs in an infinite loop until manually killed.
> Small, incremental backups seem to succeed.
>
> One duplicity command that always hangs is below. The problem also
> occurs without the --full-if-older-than and --volsize parameters.
>
> duplicity --name duply_photography --encrypt-key XXX --sign-key XXX
> --verbosity 9 --gpg-options --compress-algo=bzip2 --bzip2-compress-
> level=9 --personal-cipher-preferences AES256,AES192 --full-if-older-
> than 1Y --volsize 500 --exclude-filelist
> /root/.duply/photography/exclude / b2://xxx@xxx/photography
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/duplicity/+bug/1732269/+subscriptions
>

[Rick Gabriel (klaxian1)]

I am running Linux Mint 18.2 (based on Ubuntu xenial 16.04 LTS). Full system specs are below. There is at least 12GB free memory for duplicity and it doesn't appear to be using much when it hangs. I am in the middle of a large backup right now (with 0.7.14) so I won't be able to upload a log using 0.7.15 for a couple days. I will try to get a more detailed strace too because there wasn't any useful information nor errors in the log.

System: Host: xxx Kernel: 4.13.0-17-generic x86_64 (64 bit)
           Desktop: MATE 1.18.0 Distro: Linux Mint 18.2 Sonya
Machine: Mobo: ASUSTeK model: ROG STRIX B350-F GAMING v: Rev X.0x
           Bios: American Megatrends v: 1001 date: 09/29/2017
CPU: Quad core AMD Ryzen 3 1300X (-MCP-) speed/max: 3493/3500 MHz
Graphics: Card: NVIDIA GM107 [GeForce GTX 750 Ti]
           Display Server: X.Org 1.18.4 driver: nvidia
           Resolution: 2560x1440@59.95hz, 2560x1440@59.95hz
           GLX Renderer: GeForce GTX 750 Ti/PCIe/SSE2
           GLX Version: 4.6.0 NVIDIA 387.12
Network: Card: Intel I211 Gigabit Network Connection driver: igb
Drives: HDD Total Size: 18123.6GB (17.5% used)
RAID: Devices: 1: /dev/md3 2: /dev/md0
Info: Processes: 236 Uptime: 17:57 Memory: 1407.1/16043.9MB
           Client: Shell (bash) inxi: 2.2.35

[Kenneth Loafman (kenneth-loafman)]

Please try the 0.7.0 version of B2 first. That might just save a lot of
debugging.

$ sudo pip install -U b2==0.7.0

On Thu, Nov 16, 2017 at 9:54 AM, Rick Gabriel <email address hidden>
wrote:

> I am running Linux Mint 18.2 (based on Ubuntu xenial 16.04 LTS). Full
> system specs are below. There is at least 12GB free memory for duplicity
> and it doesn't appear to be using much when it hangs. I am in the middle
> of a large backup right now (with 0.7.14) so I won't be able to upload a
> log using 0.7.15 for a couple days. I will try to get a more detailed
> strace too because there wasn't any useful information nor errors in the
> log.
>
> System: Host: xxx Kernel: 4.13.0-17-generic x86_64 (64 bit)
> Desktop: MATE 1.18.0 Distro: Linux Mint 18.2 Sonya
> Machine: Mobo: ASUSTeK model: ROG STRIX B350-F GAMING v: Rev X.0x
> Bios: American Megatrends v: 1001 date: 09/29/2017
> CPU: Quad core AMD Ryzen 3 1300X (-MCP-) speed/max: 3493/3500 MHz
> Graphics: Card: NVIDIA GM107 [GeForce GTX 750 Ti]
> Display Server: X.Org 1.18.4 driver: nvidia
> Resolution: 2560x1440@59.95hz, 2560x1440@59.95hz
> GLX Renderer: GeForce GTX 750 Ti/PCIe/SSE2
> GLX Version: 4.6.0 NVIDIA 387.12
> Network: Card: Intel I211 Gigabit Network Connection driver: igb
> Drives: HDD Total Size: 18123.6GB (17.5% used)
> RAID: Devices: 1: /dev/md3 2: /dev/md0
> Info: Processes: 236 Uptime: 17:57 Memory: 1407.1/16043.9MB
> Client: Shell (bash) inxi: 2.2.35
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1732269
>
> Title:
> B2 always fails (hung) with 0.7.15
>
> Status in Duplicity:
> In Progress
>
> Bug description:
> Duplicity 0.7.15 consistently fails to backup to my B2. I think it
> might only affect large, full backups with multiple volumes. Some time
> after the upload of the first volume is underway, the duplicity
> process will begin using 100% CPU. strace reveals one of the
> following, depending on whether duplicity is run in async or sync
> mode:
>
> ASYNC: futex(0x1367b10, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME,
> 0, NULL, ffffffff
> SYNC: select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>
> Duplicity 0.7.14 seems to work normally. Unfortunately, no errors nor
> unusual messages are reported in the log, even with verbosity 9. The
> application just hangs in an infinite loop until manually killed.
> Small, incremental backups seem to succeed.
>
> One duplicity command that always hangs is below. The problem also
> occurs without the --full-if-older-than and --volsize parameters.
>
> duplicity --name duply_photography --encrypt-key XXX --sign-key XXX
> --verbosity 9 --gpg-options --compress-algo=bzip2 --bzip2-compress-
> level=9 --personal-cipher-preferences AES256,AES192 --full-if-older-
> than 1Y --volsize 500 --exclude-filelist
> /root/.duply/photography/exclude / b2://xxx@xxx/photography
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/duplicity/+bug/1732269/+subscriptions
>

[Rick Gabriel (klaxian1)]

Sorry for the delay. I have attached snippets of the duplicity log (verbosity 9) and an strace of the process right before it hangs in an infinite loop. Some of the names have been changed to protect the innocent. I will next test with b2 0.7.0 as suggested.

[Rick Gabriel (klaxian1)]

I confirmed the same problem occurs with python b2 version 0.7.0. Also, duplicity 0.7.14 with b2 1.0.0 works fine. It normally doesn't enter the infinite loop until after 2 or 3 volumes have been uploaded.

[Kenneth Loafman (kenneth-loafman)]

It looks like you installed b2 originally from the repo, yes? If so, pip may not be able to upgrade to 0.7.0, or will do so in a path that leaves the 1.0.0 version first on the path. Did you uninstall the 1.0.0 version first?

[Thorsten Sperber (thursday)]

I have a very similar looking problem with the azure backend, on duplicity 0.7.12, azure-storage on 0.36.0. After 2-3 days of transfers, the backup is stuck. Last lines:

AsyncScheduler: scheduling task for asynchronous execution
Deleting /tmp/duplicity-JwXGFd-tempdir/mktemp-DnsrJZ-17384
Forgetting temporary file /tmp/duplicity-JwXGFd-tempdir/mktemp-DnsrJZ-17384
AsyncScheduler: task execution done (success: True)
AsyncScheduler: active workers = 0
AsyncScheduler: active workers = 1
Processed volume 17384
Writing duplicity-full.20171128T095929Z.vol17384.difftar
Deleting /tmp/duplicity-JwXGFd-tempdir/mktemp-To0kCI-17385
Forgetting temporary file /tmp/duplicity-JwXGFd-tempdir/mktemp-To0kCI-17385
AsyncScheduler: task execution done (success: True)
AsyncScheduler: active workers = 0

And that's it. As described by klaxian1, strace repeatedly outputs select(0, NULL... ) = 0 (Timeout)

For the debug logfile (which I have), I need to mask filenames and stuff first (and cut down to the relevant parts - 35M logfile). There's no encryption or compression involved, but I use the async option. Let me know if you think that would help. For the bug to trigger, I need around 2-3 days of transfer.

I believe the bug described is (at least partially) independent of the backend, which is why I attach myself here.

[Rick Gabriel (klaxian1)]

@kenneth-loafman
You were right; when I initially used pip to downgrade to b2 0.7.0, it left 1.0.0 in my path. After explicitly uninstalling b2 1.0.0 and then installing 0.7.0, the problem appears resolved. However, this begs a few more questions.

When I upgraded to duplicity 0.7.15 using the Ubuntu PPA, I did not have any python b2 lib installed. I assume that earlier versions had built-in support for b2. The duplicity deb package does not suggest anything related to b2. I discovered that I had to install python b2 after duplicity initially died with a python backtrace indicating missing dependencies.

Is there an Ubuntu/deb package that provides python b2? I couldn't find one. If such a package exists, can the duplicity deb package be updated to require it as a dependency or at least suggest it? Can duplicity check for python b2 gracefully when attempting to backup to a b2 destination rather than crashing with a cryptic error? If duplicity is currently incompatible with python b2 1.0.0, can you explicitly check for version 0.7.0 before running? Can duplicity be made compatible with b2 1.0.0?

Without additional safeguards, I think others might run into this problem in the future. They might not know how to resolve it, especially if they are using a GUI wrapper. Cheers.

[Kenneth Loafman (kenneth-loafman)]

Thanks for the feedback. Sometimes we screw up and it hurts everyone.

The b2 package would have needed to be installed, even from the PPA. We only supply the basic required packages. There are a lot of backends. The previous b2 worked from the start because it only used raw web interface. The new b2 is much faster, but does use the official API.

"pip install -U b2==0.7.0" should have downgraded the 1.0.0 version to 0.7.0. When I ran it on my system, it uninstalled 1.0.0 and installed 0.7.0. Make sure you have an updated pip and that you used the "-U" option.

As far as I know there is no b2 deb package. PyPi (pip) is the main repository for all things Python and has the latest versions, and it's easy to select older versions if needed.

[Kenneth Loafman (kenneth-loafman)]

Needs warning that b2 package should be installed at version 0.7.0.

[Vincent Rouille (speedy37)]

I did a quick diff on b2 repository, 0.7.0 & 0.7.2 should be ok, 0.7.4 - 1.1.0 are likelly to cause troubles (it maybe unrelated but they did some changes on how and when the sha1 checksum is computed and send).

[Chris Shelton (cshelton1409)]

I am also having nearly the exact same issue as in the description of this ticket. I have been using duplicity 0.7.17 for the past several months, and have seen roughly half of my longer backups fail to complete. I am using the b2 backend with 200MB sized volumes that are gpg encrypted. The only difference for me is that when duplicity hangs, it is not using a significant amount of CPU. The local system that is having this problem was running Ubuntu 17.10 when the issue began happening. After an upgrade to Ubuntu 18.04, the same problem continues.

I have tried switching between multiple versions of the b2 pip packages, including 1.1.0, 1.0.0, 0.7.2 and 0.7.0, and all of these versions have the same behavior. The duplicity process proceeds normally, and is able to send many volumes just fine, then just stalls. My most current hung backup has hung after creating 325 volumes. Several times the process hangs for more than 24 hours, only stopping after I manually kill the duplicity process.

Usually, smaller backups work OK, and larger backups, especially full backups, have been prone to having this issue over the past several weeks. When the process is hung, the contents of an strace on the duplicity process are really minimal:

root@penelope:/var/log# ps auwx | grep dup
root 7096 0.0 0.0 4628 816 pts/5 S 08:35 0:00 /bin/sh ./duplicity_backup_media_to_b2.sh
root 7107 5.5 1.0 992016 88588 pts/5 Sl 08:35 20:13 /usr/bin/python /usr/bin/duplicity --sign-key 037C1434 --encrypt-key 2BDCCF91 --full-if-older-than 31D --asynchronous-upload --verbosity 9 /media/mybook1/media b2://dfefa127cff1:001b092ae1120aba3318aa656aad19b0c5eaa182b0@penelope-media/media

root@penelope:/var/log# strace -p 7107
strace: Process 7107 attached futex(0x55a34d6e9b10, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, 0xffffffff^C
strace: Process 7107 detached <detached ...>

I can provide a level 9 verbosity log file, but the file for my most recent run is rather large, over 21MB in size.

[Rick Gabriel (klaxian1)]

I have the same problem as @cshelton1409, but it might not be the exact one reported in this issue. Many of my large backups fail. In my case, it looks like some sort of infinite loop where one core is utilized 100% forever, but no progress is made. Nothing relevant is recorded in the logs, even with verbosity 9.

[Rob Shepherd (rgshepherd)]

I too am trying to get duply/duplicity/B2 working but something is causing a 100% CPU lock-up.

python2 /usr/bin/duplicity list-current-files --archive-dir /var/duplicity/main/cache --name duply_vpn --no-encryption --verbosity 4 --exclude-if-present=.duplicity-ignore --full-if-older-than=1D --volsize=512 --exclude **/hs_err_pid*.log -v3 b2://<user>@<bucket>

I have pegged B2 at 0.7.0 as discussed above.

The infrequently changing backup set of about 200kb takes over 10 minutes to perform a list operation, even when local and remote are already synchronised.

Here is a duply trace. Notice the gap between 06:19:53 and 06:32:18 during which time the CPU sits at 100%

The summary is:

> SourceFileSize 193296 (189 KB)
> TotalDestinationSizeChange 20 (20 bytes)
> Runtime 00:12:45.005

Feb 12 06:19:37 neutrino duply-vpn: Start duply v1.11, time is 2019-02-12 06:16:01.
Feb 12 06:19:37 neutrino duply-vpn: Using profile '/etc/duply/vpn'.
Feb 12 06:19:37 neutrino duply-vpn: Using installed duplicity version 0.7.16, python 2.7.12, gpg 1.4.20 (Home: ~/.gnupg), awk 'GNU Awk 4.1.3, API: 1.1 (GNU MPFR 3.1.4, GNU MP 6.1.0)', grep 'grep (GNU grep) 2.25', bash '4.3.48(1)-release (x86_64-pc-linux-gnu)'.
Feb 12 06:19:37 neutrino duply-vpn: Checking TEMP_DIR '/tmp' is a folder and writable (OK)
Feb 12 06:19:37 neutrino duply-vpn: Test - En/Decryption skipped. (GPG disabled)
Feb 12 06:19:37 neutrino duply-vpn: --- Start running command PRE at 06:16:01.651 ---
Feb 12 06:19:37 neutrino duply-vpn: Skipping n/a script '/etc/duply/vpn/pre'.
Feb 12 06:19:37 neutrino duply-vpn: --- Finished state OK at 06:16:01.673 - Runtime 00:00:00.021 ---
Feb 12 06:19:37 neutrino duply-vpn: --- Start running command INCR at 06:16:01.690 ---
Feb 12 06:19:39 neutrino duply-vpn: Reading globbing filelist /etc/duply/vpn/exclude
Feb 12 06:19:53 neutrino duply-vpn: Local and Remote metadata are synchronized, no sync needed.
Feb 12 06:32:18 neutrino duply-vpn: Last full backup date: Tue Feb 12 00:00:05 2019
Feb 12 06:32:22 neutrino duply-vpn: --------------[ Backup Statistics ]--------------
Feb 12 06:32:22 neutrino duply-vpn: StartTime 1549952923.53 (Tue Feb 12 06:28:43 2019)
Feb 12 06:32:22 neutrino duply-vpn: EndTime 1549952923.56 (Tue Feb 12 06:28:43 2019)
Feb 12 06:32:22 neutrino duply-vpn: ElapsedTime 0.03 (0.03 seconds)
Feb 12 06:32:22 neutrino duply-vpn: SourceFiles 101
Feb 12 06:32:22 neutrino duply-vpn: SourceFileSize 193296 (189 KB)
Feb 12 06:32:22 neutrino duply-vpn: NewFiles 0
Feb 12 06:32:22 neutrino duply-vpn: NewFileSize 0 (0 bytes)
Feb 12 06:32:22 neutrino duply-vpn: DeletedFiles 0
Feb 12 06:32:22 neutrino duply-vpn: ChangedFiles 0
Feb 12 06:32:22 neutrino duply-vpn: ChangedFileSize 0 (0 bytes)
Feb 12 06:32:22 neutrino duply-vpn: ChangedDeltaSize 0 (0 bytes)
Feb 12 06:32:22 neutrino duply-vpn: DeltaEntries 0
Feb 12 06:32:22 neutrino duply-vpn: RawDeltaSize 0 (0 bytes)
Feb 12 06:32:22 neutrino duply-vpn: TotalDestinationSizeChange 20 (20 bytes)
Feb 12 06:32:22 neutrino duply-vpn: Errors 0
Feb 12 06:32:22 neutrino duply-vpn: -------------------------------------------------
Feb 12 06:32:22 neutrino duply-vpn: --- Finished state OK at 06:28:46.696 - Runtime 00:12:45.005 ---
F...