acd_cli backend: Name collision with non-cached file

[Juan Orti Alcaine]

Hi,

I have frequent errors uploading using the acd_cli backend. It seems that after a connection error like "Read timed out", the next tries fail with "Name collision with non-cached file. If you want to overwrite, please sync and try again."

I guess that the backend should do a "acd_cli sync" before any subsequent tries to avoid this?

I'm using Fedora 25 x86_64, with these packages:
duplicity-0.7.10-1.fc25.x86_64
python-2.7.12-7.fc25.x86_64

---------------------------

This is a snip of the error:

A mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031
AsyncScheduler: running task synchronously (asynchronicity disabled)
Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 8, with output:
[ ] 0.0% of 200MiB 0/1 -70.1MB/s 0s
1 file(s) failed.

16-11-08 14:32:50.630 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. RequestError: 1000, HTTPSConnectionPool(host='content-eu.drive.amazonaws.com', port=443): Read timed out.
(read timeout=60).

Attempt 1 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 8, with ou$
put:
[ ] 0.0% of 200MiB 0/1 -70.1MB/s 0s
1 file(s) failed.

16-11-08 14:32:50.630 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. RequestError: 1000, HTTPSConnectionPool(host='content-eu.drive.amazonaws.com', port=443): Read timed out.
(read timeout=60).

Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 15.4MB/s 0s
1 file(s) failed.

16-11-08 14:33:36.932 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:33:36.988 [WARNING] [acd_cli] - Return value error code: 256.

Attempt 2 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with ou$
put:
[#########################] 100.0% of 201MiB 1/1 15.4MB/s 0s
1 file(s) failed.

---------------------------

I launch duplicity with duply, this is the beginning of the run:

Start duply v1.11.3, time is 2016-11-08 11:25:04.
Using profile '/etc/duply/acd'.
Using installed duplicity version 0.7.10, python 2.7.12, gpg 1.4.21 (Home: ~/.gnupg), awk 'GNU Awk 4.1.3, API: 1.1 (GNU MPFR 3.1.5, GNU MP 6.1.1)', grep 'grep (GNU grep) 2.26', bash '4.3.43(1)-release (x86_64-redhat-linux-gnu)'.
Autoset found secret key of first GPG_KEY entry '<removed>' for signing.
Checking TEMP_DIR '/tmp' is a folder and writable (OK)
Test - Encrypt to <removed> & Sign with <removed> (OK)
Test - Decrypt (OK)
Test - Compare (OK)
Cleanup - Delete '/tmp/duply.1471.1478600704_*'(OK)

--- Start running command PRE at 11:25:05.164 ---
Running '/etc/duply/acd/pre' - OK
Output: Create a readonly snapshot of '/mnt/btrfs/libvirt-images' in '/mnt/btrfs/libvirt-images@DuplicityBackup'
Create a readonly snapshot of '/mnt/btrfs/BorgBackup' in '/mnt/btrfs/BorgBackup@DuplicityBackup'
Getting changes..
Inserting nodes.
--- Finished state OK at 11:25:13.306 - Runtime 00:00:08.141 ---

--- Start running command BKP at 11:25:13.314 ---
Using archive dir: /root/backups/duply-cache/duply_acd
Using backup name: duply_acd
Import of duplicity.backends.acdclibackend Succeeded
Import of duplicity.backends.azurebackend Succeeded
Import of duplicity.backends.b2backend Succeeded
Import of duplicity.backends.botobackend Succeeded
Import of duplicity.backends.cfbackend Succeeded
Import of duplicity.backends.copycombackend Succeeded
Import of duplicity.backends.dpbxbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.hubicbackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.lftpbackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.mediafirebackend Succeeded
Import of duplicity.backends.megabackend Succeeded
Import of duplicity.backends.multibackend Succeeded
Import of duplicity.backends.ncftpbackend Succeeded
Import of duplicity.backends.onedrivebackend Succeeded
Import of duplicity.backends.par2backend Succeeded
Import of duplicity.backends.pydrivebackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.ssh_paramiko_backend Succeeded
Import of duplicity.backends.ssh_pexpect_backend Succeeded
Import of duplicity.backends.swiftbackend Succeeded
Import of duplicity.backends.sxbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Reading results of 'acd_cli sync'
Reading results of 'acd_cli ls '/Backups/xenon/duplicity/''
Reading globbing filelist /etc/duply/acd/exclude
Main action: inc
================================================================================
duplicity 0.7.10 (August 20, 2016)
Args: /usr/bin/duplicity --archive-dir /root/backups/duply-cache --name duply_acd --encrypt-key <removed> --encrypt-key <removed> --sign-key <removed> --verbosity 9 --full-if-older-than 6M --exclude-filelist /etc/duply/acd/exclude / acd+acdcli:///Backups/xenon/duplicity/
Linux xenon 4.8.6-300.fc25.x86_64 #1 SMP Tue Nov 1 12:36:38 UTC 2016 x86_64 x86_64
/usr/bin/python2 2.7.12 (default, Sep 29 2016, 12:52:02)
[GCC 6.2.1 20160916 (Red Hat 6.2.1-2)]
================================================================================
Using temporary directory /tmp/duplicity-9DdCo1-tempdir
Registering (mkstemp) temporary file /tmp/duplicity-9DdCo1-tempdir/mkstemp-aXYQsN-1
Temp has 8326713344 available, backup will use approx 272629760.
Reading results of 'acd_cli ls '/Backups/xenon/duplicity/''
Local and Remote metadata are synchronized, no sync needed.
Reading results of 'acd_cli ls '/Backups/xenon/duplicity/''
6416 files exist on backend
10 files exist in cache
Extracting backup chains from list of files: [<removed>]
File duplicity-new-signatures.20161101T221724Z.to.20161108T061533Z.sigtar.part is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-new-signatures.20161101T221724Z.to.20161108T061533Z.sigtar.part'
File duplicity-inc.20161101T221724Z.to.20161108T061533Z.manifest.part is not part of a known set; creating new set
Processing local manifest /root/backups/duply-cache/duply_acd/duplicity-inc.20161101T221724Z.to.20161108T061533Z.manifest.part (67267)
Found manifest volume 1
Found manifest volume 2
Found manifest volume 3
[...]

---------------------------

And the las 200 lines:

juan@juan-laptop:~/Descargas$ tail -n 200 duplicity.log
Selection: examining path /mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2030
Selection: result: None from function: Command-line exclude glob: /root/.cache/**
Selection: result: None from function: Command-line exclude glob: /root/.ccache/**
Selection: result: None from function: Command-line exclude glob: /home/*/Descargas/**
Selection: result: None from function: Command-line exclude glob: /home/*/.local/share/Trash/**
Selection: result: None from function: Command-line exclude glob: /home/*/.cache/**
Selection: result: None from function: Command-line exclude glob: /home/*/.ccache/**
Selection: result: None from function: Command-line exclude glob: /mnt/backups/duply-cache/**
Selection: result: None from function: Command-line include glob: /etc/**
Selection: result: None from function: Command-line include glob: /root/**
Selection: result: None from function: Command-line include glob: /var/spool/cron/**
Selection: result: None from function: Command-line include glob: /home/**
Selection: result: None from function: Command-line include glob: /opt/**
Selection: result: None from function: Command-line include glob: /usr/local/**
Selection: result: None from function: Command-line include glob: /mnt/backups/**
Selection: result: None from function: Command-line include glob: /mnt/btrfs/libvirt-images@DuplicityBackup/**
Selection: result: 1 from function: Command-line include glob: /mnt/btrfs/BorgBackup@DuplicityBackup/**
Selection: + including file
Selecting /mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2030
Comparing mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2030 and None
Getting delta of (mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2030 reg) and None
A mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2030
Selection: examining path /mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031
Selection: result: None from function: Command-line exclude glob: /root/.cache/**
Selection: result: None from function: Command-line exclude glob: /root/.ccache/**
Selection: result: None from function: Command-line exclude glob: /home/*/Descargas/**
Selection: result: None from function: Command-line exclude glob: /home/*/.local/share/Trash/**
Selection: result: None from function: Command-line exclude glob: /home/*/.cache/**
Selection: result: None from function: Command-line exclude glob: /home/*/.ccache/**
Selection: result: None from function: Command-line exclude glob: /mnt/backups/duply-cache/**
Selection: result: None from function: Command-line include glob: /etc/**
Selection: result: None from function: Command-line include glob: /root/**
Selection: result: None from function: Command-line include glob: /var/spool/cron/**
Selection: result: None from function: Command-line include glob: /home/**
Selection: result: None from function: Command-line include glob: /opt/**
Selection: result: None from function: Command-line include glob: /usr/local/**
Selection: result: None from function: Command-line include glob: /mnt/backups/**
Selection: result: None from function: Command-line include glob: /mnt/btrfs/libvirt-images@DuplicityBackup/**
Selection: result: 1 from function: Command-line include glob: /mnt/btrfs/BorgBackup@DuplicityBackup/**
Selection: + including file
Selecting /mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031
Comparing mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031 and None
Getting delta of (mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031 reg) and None
A mnt/btrfs/BorgBackup@DuplicityBackup/nologin-laptop/repo/data/0/2031
AsyncScheduler: running task synchronously (asynchronicity disabled)
Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 8, with output:
[ ] 0.0% of 200MiB 0/1 -70.1MB/s 0s
1 file(s) failed.

16-11-08 14:32:50.630 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. RequestError: 1000, HTTPSConnectionPool(host='content-eu.drive.amazonaws.com', port=443): Read timed out. (read timeout=60).

Attempt 1 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 8, with output:
[ ] 0.0% of 200MiB 0/1 -70.1MB/s 0s
1 file(s) failed.

16-11-08 14:32:50.630 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. RequestError: 1000, HTTPSConnectionPool(host='content-eu.drive.amazonaws.com', port=443): Read timed out. (read timeout=60).

Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 15.4MB/s 0s
1 file(s) failed.

16-11-08 14:33:36.932 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:33:36.988 [WARNING] [acd_cli] - Return value error code: 256.

Attempt 2 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 15.4MB/s 0s
1 file(s) failed.

16-11-08 14:33:36.932 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:33:36.988 [WARNING] [acd_cli] - Return value error code: 256.

Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 11.4MB/s 0s
1 file(s) failed.

16-11-08 14:34:24.131 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:34:24.281 [WARNING] [acd_cli] - Return value error code: 256.

Attempt 3 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 11.4MB/s 0s
1 file(s) failed.

16-11-08 14:34:24.131 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:34:24.281 [WARNING] [acd_cli] - Return value error code: 256.

Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 11.9MB/s 0s
1 file(s) failed.

16-11-08 14:35:17.100 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:35:17.363 [WARNING] [acd_cli] - Return value error code: 256.

Attempt 4 failed. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 11.9MB/s 0s
1 file(s) failed.

16-11-08 14:35:17.100 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:35:17.363 [WARNING] [acd_cli] - Return value error code: 256.

Writing duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg
Reading results of 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/''
Backtrace of previous error: Traceback (innermost last):
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 369, in inner_retry
    return fn(self, *args)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 522, in put
    self.__do_put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 508, in __do_put
    self.backend._put(source_path, remote_filename)
  File "/usr/lib64/python2.7/site-packages/duplicity/backends/acdclibackend.py", line 94, in _put
    l = self.subprocess_popen(commandline)
  File "/usr/lib64/python2.7/site-packages/duplicity/backend.py", line 492, in subprocess_popen
    (private, result, stdout + '\n' + stderr))
 BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 9.8MB/s 0s
1 file(s) failed.

16-11-08 14:36:07.875 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:36:07.967 [WARNING] [acd_cli] - Return value error code: 256.

Giving up after 5 attempts. BackendException: Error running 'acd_cli upload --force --overwrite '/tmp/duplicity-9DdCo1-tempdir/duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg' '/Backups/xenon/duplicity/'': returned 1, with output:
[#########################] 100.0% of 201MiB 1/1 9.8MB/s 0s
1 file(s) failed.

16-11-08 14:36:07.875 [ERROR] [acd_cli] - Uploading "duplicity-inc.20161101T221724Z.to.20161108T061533Z.vol466.difftar.gpg" failed. Name collision with non-cached file. If you want to overwrite, please sync and try again.
16-11-08 14:36:07.967 [WARNING] [acd_cli] - Return value error code: 256.

Releasing lockfile /root/backups/duply-cache/duply_acd/lockfile.lock
Removing still remembered temporary file /tmp/duplicity-9DdCo1-tempdir/mkstemp-aXYQsN-1
Removing still remembered temporary file /tmp/duplicity-9DdCo1-tempdir/mktemp-OIkbZn-253
14:36:08.210 Task 'BKP' failed with exit code '50'.
--- Finished state FAILED 'code 50' at 14:36:08.210 - Runtime 03:10:54.896 ---

--- Start running command POST at 14:36:08.233 ---
Running '/etc/duply/acd/post' - OK
Output: Delete subvolume (commit): '/mnt/btrfs/libvirt-images@DuplicityBackup'
Delete subvolume (commit): '/mnt/btrfs/BorgBackup@DuplicityBackup'
--- Finished state OK at 14:36:10.059 - Runtime 00:00:01.825 ---

[Juan Orti Alcaine (juan.orti)]

After more testing, it looks like the failed upload is creating the file in ACD, so subsequent retries fail because of name collisions.

If I manually trash the file, the backup can continue.

I guess the right fix would be for acd_cli to update its file cache if the file has been created, but could you add in the duplicity backend an "acd_cli trash <file>" as a workaround?

Kind regards.

[Juan Orti Alcaine (juan.orti)]

I've opened the acd_cli bug #487

https://github.com/yadayada/acd_cli/issues/487