duplicity stuck in splice() call on Bionic

[Václav Haisman]

I am using Duplicity through Deja-Dup through its deja-dup-monitor process. After update to Bionic, it has basically stopped doing backups. Version is duplicity 0.7.17+bzr1357, Python version is 2.7.15rc1, Xubuntu Bionic.

It seems to be stuck in pipes related call. When I try to strace the process I get this:

strace: Process 28490 attached
splice(9, [359], 16, NULL, 1048576, SPLICE_F_MORE

From handle 9 to 16. The handle 9 is a file on my CIFS mount to where I do backups. If I go to the directory and do ls it works fine:

duplicity 28490 USER 9r REG 0,52 359 67128742 /var/backups/USER/backup.HOST/duplicity-inc.20180611T014226Z.to.20180612T014125Z.manifest.gpg

Handle 16 is a pipe:

duplicity 28490 USER 16w FIFO 0,12 0t0 1415081 pipe

Its other end is handle 13, I think:

duplicity 28490 USER 13r FIFO 0,12 0t0 1415081 pipe

But I do not see anyone reading from it. That sounds like the issue.

It seems to be stuck in GIO file handling code:

(gdb) bt
#0 0x00007f0e78588dda in splice (fd_in=9, off_in=0x7ffe5e958388, fd_out=16, off_out=0x0, len=1048576, flags=4) at ../sysdeps/unix/sysv/linux/splice.c:26
#1 0x00007f0e6ee2672e in () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#2 0x00007f0e6ee2d827 in g_file_copy () at /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#3 0x00007f0e76ccfdae in ffi_call_unix64 () at /usr/lib/x86_64-linux-gnu/libffi.so.6
#4 0x00007f0e76ccf71f in ffi_call () at /usr/lib/x86_64-linux-gnu/libffi.so.6
#5 0x00007f0e6fb8ecfa in () at /usr/lib/python2.7/dist-packages/gi/_gi.x86_64-linux-gnu.so
#6 0x00007f0e6fb908e8 in () at /usr/lib/python2.7/dist-packages/gi/_gi.x86_64-linux-gnu.so
#7 0x00007f0e6fb84c39 in () at /usr/lib/python2.7/dist-packages/gi/_gi.x86_64-linux-gnu.so
#8 0x00005560917a1f60 in PyEval_EvalFrameEx ()

I have already tried to restart it and it got stuck like this again the next backup cycle.

[Kenneth Loafman (kenneth-loafman)]

Strange!

Please post the command line duplicity is using.

Start the backup with:
  $ DEJA_DUP_DEBUG=1 deja-dup --backup
This should produce a very detailed log. At the point that it hangs in splice(), use Ctrl-C to stop the tasks. Add the log as an attachment using the green '+' button below.

[Václav Haisman (vzeman79)]

There appears to be some sort of IO error when it tries to ask for GPG password. But then it keeps working for some time and then it gets stuck.

[Václav Haisman (vzeman79)]

The command lines are visible also in the logs:

/usr/bin/python /usr/bin/duplicity --exclude=/var/backups/USER/backup.HOST --exclude=/home/USER/snap/*/*/.cache --include=/home/USER/.cache/deja-dup/metadata --exclude=/home/USER/Private --exclude=/home/USER/.local/share/Trash --exclude=/home/USER/.xsession-errors --exclude=/home/USER/.thumbnails --exclude=/home/USER/.steam/root --exclude=/home/USER/.adobe/Flash_Player/AssetCache --exclude=/home/USER/.cache/deja-dup --exclude=/home/USER/.cache --exclude=/home/USER/.steam --include=/home/USER --exclude=/sys --exclude=/run --exclude=/proc --exclude=/var/tmp --exclude=/tmp --exclude=** --dry-run --volsize=50 / gio+file:///var/backups/USER/backup.HOST --verbosity=9 --gpg-options=--no-use-agent --archive-dir=/home/USER/.cache/deja-dup --tempdir=/tmp --log-fd=18

[Václav Haisman (vzeman79)]

This is the error:

DUPLICITY: INFO 1
DUPLICITY: . PASSPHRASE variable not set, asking user.

DUPLICITY: DEBUG 1
DUPLICITY: . Releasing lockfile /home/USER/.cache/deja-dup/26fe42a2cb8bb6db7dff2a2938d67b37/lockfile

DUPLICITY: DEBUG 1
DUPLICITY: . Removing still remembered temporary file /tmp/duplicity-PqgMYo-tempdir/mkstemp-Z09X9e-1

DUPLICITY: DEBUG 1
DUPLICITY: . Releasing lockfile /home/USER/.cache/deja-dup/26fe42a2cb8bb6db7dff2a2938d67b37/lockfile

DUPLICITY: ERROR 30 EOFError
DUPLICITY: . Traceback (innermost last):
DUPLICITY: . File "/usr/bin/duplicity", line 1567, in <module>
DUPLICITY: . with_tempdir(main)
DUPLICITY: . File "/usr/bin/duplicity", line 1553, in with_tempdir
DUPLICITY: . fn()
DUPLICITY: . File "/usr/bin/duplicity", line 1405, in main
DUPLICITY: . do_backup(action)
DUPLICITY: . File "/usr/bin/duplicity", line 1481, in do_backup
DUPLICITY: . globals.gpg_profile.passphrase = get_passphrase(1, action)
DUPLICITY: . File "/usr/bin/duplicity", line 199, in get_passphrase
DUPLICITY: . pass1 = getpass_safe(_("GnuPG passphrase:") + " ")
DUPLICITY: . File "/usr/bin/duplicity", line 96, in getpass_safe
DUPLICITY: . return getpass.getpass(message)
DUPLICITY: . File "/usr/lib/python2.7/getpass.py", line 83, in unix_getpass
DUPLICITY: . passwd = fallback_getpass(prompt, stream)
DUPLICITY: . File "/usr/lib/python2.7/getpass.py", line 118, in fallback_getpass
DUPLICITY: . return _raw_input(prompt, stream)
DUPLICITY: . File "/usr/lib/python2.7/getpass.py", line 135, in _raw_input
DUPLICITY: . raise EOFError
DUPLICITY: . EOFError
DUPLICITY: .

[Kenneth Loafman (kenneth-loafman)]

You'll need to supply a PASSPHRASE environment variable since --gpg-options=--no-use-agent is specified, something like:

$ PASSPHRASE=foo deja-dup backup

[Václav Haisman (vzeman79)]

Is that true? Haven't I set up the pass phrase during initial backup in Deja Dup? It does not make sense for automatic backup to as for passhrase each time it runs. Is this Deja Dup issue then?

[Kenneth Loafman (kenneth-loafman)]

Have you tried https://bugs.launchpad.net/duplicity/+bug/1778638/comments/6 yet??

Please let me know if it worked.

[Václav Haisman (vzeman79)]

I have even tried without encryption. The `--no-use-agent` option is there even:

DUPLICITY: . Args: /usr/bin/duplicity --exclude=/var/backups/wilx/backup.amber2 --exclude=/home/wilx/snap/*/*/.cache --include=/home/wilx/.cache/deja-dup/metadata --exclude=/home/wilx/Private --exclude=/home/wilx/.local/share/Trash --exclude=/home/wilx/.xsession-errors --exclude=/home/wilx/.thumbnails --exclude=/home/wilx/.steam/root --exclude=/home/wilx/.adobe/Flash_Player/AssetCache --exclude=/home/wilx/.cache/deja-dup --exclude=/home/wilx/.cache --exclude=/home/wilx/.steam --include=/home/wilx --exclude=/sys --exclude=/run --exclude=/proc --exclude=/var/tmp --exclude=/tmp --exclude=** --dry-run --volsize=50 / gio+file:///var/backups/wilx/backup.amber2 --no-encryption --verbosity=9 --gpg-options=--no-use-agent --archive-dir=/home/wilx/.cache/deja-dup --tempdir=/tmp --log-fd=13

It still gets stuck in the `splice()` call.

#0 0x00007f4b979efdda in splice (fd_in=9, off_in=0x7ffd5ff098f8, fd_out=15, off_out=0x0, len=1048576, flags=4) at ../sysdeps/unix/sysv/linux/splice.c:26

Nobody is reading from the pipe:

duplicity 1328 wilx 9r REG 0,52 214 45574945 /var/backups/wilx/backup.amber2/duplicity-inc.20180824T154037Z.to.20180825T014020Z.manifest

duplicity 1328 wilx 14r FIFO 0,12 0t0 28167742 pipe
duplicity 1328 wilx 15w FIFO 0,12 0t0 28167742 pipe

[Václav Haisman (vzeman79)]

Further debugging with `strace` shows it literally creates the pipe right before it tries to write into it:

write(1, "Registering (mktemp) temporary f"..., 82) = 82
write(13, "DEBUG 1\n. Registering (mktemp) t"..., 93) = 93
lstat("/tmp/duplicity-iMtvLG-tempdir/mktemp-Z8PNlG-2", 0x7ffd210b6cc0) = -1 ENOENT (No such file or directory)
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
lstat("/var/backups/wilx/backup.amber2/duplicity-inc.20180824T154037Z.to.20180825T014020Z.manifest", {st_mode=S_IFREG|0755, st_size=214, ...}) = 0
openat(AT_FDCWD, "/var/backups/wilx/backup.amber2/duplicity-inc.20180824T154037Z.to.20180825T014020Z.manifest", O_RDONLY) = 9
fstat(9, {st_mode=S_IFREG|0755, st_size=214, ...}) = 0
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
fstat(9, {st_mode=S_IFREG|0755, st_size=214, ...}) = 0
flistxattr(9, NULL, 0) = -1 ENODATA (No data available)
openat(AT_FDCWD, "/tmp/duplicity-iMtvLG-tempdir/mktemp-Z8PNlG-2", O_WRONLY|O_CREAT|O_EXCL, 0755) = 10
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
futex(0x7f4cce376f38, FUTEX_WAKE_PRIVATE, 2147483647) = 0
ioctl(10, BTRFS_IOC_CLONE or FICLONE, 9) = -1 EXDEV (Invalid cross-device link)

It creates the pipe descriptor pair here:

pipe2([19, 20], O_CLOEXEC) = 0
fcntl(20, F_SETPIPE_SZ, 1048576) = 1048576
fstat(9, {st_mode=S_IFREG|0755, st_size=214, ...}) = 0

And immediately tries to write into it. Who is supposed to be reading the other end?

splice(9, [0], 20, NULL, 1048576, SPLICE_F_MORE) = 214
splice(19, NULL, 10, [0], 214, SPLICE_F_MORE) = 214
splice(9, [214], 20, NULL, 1048576, SPLICE_F_MORE

The two commented chunks above are adjacent in the `strace` log. I have not left out anything. These are literally the last 6 lines of the `strace` log of the stuck process.

[Václav Haisman (vzeman79)]

It looks like this is not just me who is having this issue: https://bugzilla.redhat.com/show_bug.cgi?id=1582654

[Launchpad Janitor (janitor)]

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

[Václav Haisman (vzeman79)]

For what it is worth, Duplicity 0.8.11.1612-1 on Ubuntu 20.10 works fine.