ASCII decode error, but not due to filenames in backup target

Hello!

This looks exactly like a very old bug, that should be fixed for a while. So I am wondering if this is the old problem, which sometimes stays if people continue to use their old backups while upgrading to newer versions. So I have to ask a few questions:

When did you first configured Déjà Dup?
 Is this an old backup, which you kept, while upgrading (!) to newer versions of Ubuntu?
 When did you installed a fresh Ubuntu on that pc for the last time?

Please set the state back to new after answering!

Best regards

Vej

Ubuntu 17.04 was fresh installed in early July 2017, and I've since upgraded to 17.10 (I did not fresh install 17.10). I did not reconfigure Deja Dup before or after that upgrade.

When I did the fresh install and then set up the backup, I already had a backup directory on the secondary drive that my previous Ubuntu install had been using. But, I never configured this install to use that same directory; I've used a new directory with a different name from the get-go. So that shouldn't matter.

Looking in the backup directory, the oldest file is dated August 2, 2017. And under scheduling I have Deja Dup configured to keep at least six months, so I think that date is the real date I first configured the backup.

I have not tried configuring Deja Dup to use a new storage location since this problem started occuring. Should I try that?

Also, I should note that the backup window shows the message "Creating a fresh backup to protect against backup corruption. This will take longer than normal." Wouldn't this mean that Deja Dup is not trying to create an incremental backup on top of what was backed up in Ubuntu 17.04?

I don't know why, but the backup started working again yesterday. I did not do anything to try and fix it.

The only thing I can think of that changed on my system is that these packages were updated (from /var/log/dpkg.log):
2017-11-07 08:10:32 upgrade google-chrome-stable:amd64 62.0.3202.75-1 62.0.3202.89-1
2017-11-07 08:10:36 upgrade libssl1.0.0:amd64 1.0.2g-1ubuntu13 1.0.2g-1ubuntu13.2
2017-11-07 08:10:36 upgrade openssl:amd64 1.0.2g-1ubuntu13 1.0.2g-1ubuntu13.2

The backup worked again today. If it works again tomorrow, then that's three times and I'll call the problem fixed, somehow.

I thought of something that could be a change on the system. I dual boot Ubuntu and Windows. The target disk for backups is formatted as NTFS, and Windows 10 mounts it when it boots. I just checked the Windows logs, and the second to last time I booted Windows was just before the backup started failing. Then, the last time I booted Windows was just before the backup started working again.

Ohh, here is a thing. In Windows 10, under Control Panel > Hardware and Sound > Power Options > System Settings > Shutdown settings, Fast Startup is enabled. This option must be disabled for Ubuntu to be able to reliably use the NTFS hard drives.

I did have Fast Startup disabled. I'm guessing that the Fall Creators Update re-enabled it. Windows likes to do things like that. Stupid Windows.

Ok, I've turned off Fast Startup again. I think we can call this bug resolved, but I don't know what I should change the status to.

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

I have the almost the same system configuration as Paul Nickerson, except that backups are stored on a separate NTFS-formatted drive, that neither Ubuntu nor Windows boots. Disabling Fast Startup solved the problem for me too. Thanks for sharing the solution!

I have noticed that while Fast Startup is enabled, Ubuntu mounts the drive read-only. In my opinion there is still a bug in duplicity, as it doesn't handle this situation properly and crashes. It would be much better if it checks whether the destination is read-only and stops with a clear message, indicating the problem, instead of crashing.

Actually, that looks like what is happening — an error is bubbling up from the system and when trying to format it, duplicity is misconverting from/to Unicode and crashing. Possibly due to a translation.

Reassigning to duplicity and myself.

Take a look at the message in duplicity-team called "Help with unicode
branch (for Python3 support)".

It turns out that uexc() is using ufn() which is calling
sys.getfilesystemencoding(). We may have a fix, not implemented yet, for
sys.getfilesystemencoding() returning 'ascii' or None when called in a
detached process. Would like your thoughts on that.

On Sun, Nov 19, 2017 at 10:42 AM, Michael Terry <email address hidden> wrote:

> Actually, that looks like what is happening — an error is bubbling up
> from the system and when trying to format it, duplicity is misconverting
> from/to Unicode and crashing. Possibly due to a translation.
>
> Reassigning to duplicity and myself.
>
> ** Package changed: deja-dup (Ubuntu) => duplicity (Ubuntu)
>
> ** Also affects: duplicity
> Importance: Undecided
> Status: New
>
> ** Changed in: duplicity
> Assignee: (unassigned) => Michael Terry (mterry)
>
> --
> You received this bug notification because you are subscribed to
> duplicity in Ubuntu.
> https://bugs.launchpad.net/bugs/1729695
>
> Title:
> ASCII decode error, but not due to filenames in backup target
>
> Status in Duplicity:
> New
> Status in duplicity package in Ubuntu:
> Confirmed
>
> Bug description:
> On Ubuntu 17.10, I have deja-dup 36.2-0ubuntu1 installed. When I run
> "DEJA_DUP_DEBUG=1 deja-dup", it starts a backup as soon as it opens,
> as expected. But the backup fails. I get the following at the end of
> the output. I tried uninstalling Dropbox and deleting its .dropbox-
> dist directory, and then deja-dup crashed when trying to back up a
> completely different file (but the same byte in the same position). So
> I don't think this is due to any of the filenames I have in my backup
> target. I also tried a few commands to find non-ASCII filenames, with
> no luck. I'm not sure what else I can do to troubleshoot.
>
>
> DUPLICITY: INFO 4 'home/paul/.dropbox-dist/dropbox-lnx.x86_64-38.4.27/
> PyQt5.QtGui.so'
> DUPLICITY: . A home/paul/.dropbox-dist/dropbox-lnx.x86_64-38.4.27/PyQ
> t5.QtGui.so
>
> DUPLICITY: DEBUG 1
> DUPLICITY: . Removing still remembered temporary file
> /home/paul/.cache/deja-dup/1499b6292f58faddd30853ffbbfefc
> f6/duplicity-S72EWc-tempdir/mktemp-hYd54u-1
>
> DUPLICITY: DEBUG 1
> DUPLICITY: . Removing still remembered temporary file
> /home/paul/.cache/deja-dup/1499b6292f58faddd30853ffbbfefc
> f6/duplicity-VyBN42-tempdir/mktemp-BO1DKJ-1
>
> DUPLICITY: INFO 11
> DUPLICITY: . AsyncScheduler: running task synchronously (asynchronicity
> disabled)
>
> DUPLICITY: INFO 1
> DUPLICITY: . Writing duplicity-full.20171102T205615Z.vol1.difftar.gz
>
> DUPLICITY: DEBUG 1
> DUPLICITY: . Releasing lockfile /home/paul/.cache/deja-dup/
> 1499b6292f58faddd30853ffbbfefcf6/lockfile.lock
>
> DUPLICITY: DEBUG 1
> DUPLICITY: . Removing still remembered temporary file
> /tmp/duplicity-c9BMvB-tempdir/mktemp-RtijDc-270
>
> DUPLICITY: DEBUG 1
> DUPLICITY: . Removing still remembered temporary file
> /tmp/duplicity-c9BMvB-tempdir/mkstemp-3cxG5G-1
>
> DUPLICITY: ERROR 30 UnicodeDecodeError
> DUPLICITY: . Traceback (most recent call last):
> DUPLICITY: . File "/usr/bin/duplicit...

I suspect this is fixed in duplicity 0.7.15 now -- by commit 1318 [1].

I'm going to tentatively mark the upstream side fixed. Can someone confirm? Ubuntu bionic does not yet have 0.7.15, but it should before release.

[1] http://bazaar.launchpad.net/~duplicity-team/duplicity/0.7-series/revision/1318

Ubuntu 17.10 (duplicity 0.7.12)

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1546, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1540, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1391, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1510, in do_backup
    full_backup(col_stats)
  File "/usr/bin/duplicity", line 575, in full_backup
    globals.backend)
  File "/usr/bin/duplicity", line 434, in write_multivol
    at_end = gpg.GzipWriteFile(tarblock_iter, tdp.name, globals.volsize)
  File "/usr/lib/python2.7/dist-packages/duplicity/gpg.py", line 421, in GzipWriteFile
    new_block = block_iter.next()
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 520, in next
    result = self.process_continued()
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 700, in process_continued
    data, last_block = self.get_data_block(self.process_fp)
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 686, in get_data_block
    if fp.close():
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 440, in close
    self.callback(self.sig_gen.getsig(), *self.extra_args)
  File "/usr/lib/python2.7/dist-packages/duplicity/librsync.py", line 218, in getsig
    return ''.join(self.sigstring_list)
MemoryError

Hello

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1546, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1540, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1391, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1468, in do_backup
    restore(col_stats)
  File "/usr/bin/duplicity", line 731, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 560, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 523, in integrate_patch_iters
    for patch_seq in collated:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 389, in yield_tuples
    setrorps(overflow, elems)
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 378, in setrorps
    elems[i] = iter_list[i].next()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 107, in filter_path_iter
    for path in path_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 121, in difftar2path_iter
    tarinfo_list = [tar_iter.next()]
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 339, in next
    self.set_tarfile()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 333, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/usr/bin/duplicity", line 768, in get_fileobj_iter
    manifest.volume_info_dict[vol_num])
  File "/usr/bin/duplicity", line 811, in restore_get_enc_fileobj
    fileobj = tdp.filtered_open_with_delete("rb")
  File "/usr/lib/python2.7/dist-packages/duplicity/dup_temp.py", line 119, in filtered_open_with_delete
    fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
  File "/usr/lib/python2.7/dist-packages/duplicity/path.py", line 778, in filtered_open
    return gpg.GPGFile(False, self, gpg_profile)
  File "/usr/lib/python2.7/dist-packages/duplicity/gpg.py", line 202, in __init__
    'logger': self.logger_fp})
  File "/usr/lib/python2.7/dist-packages/duplicity/gpginterface.py", line 374, in run
    create_fhs, attach_fhs)
  File "/usr/lib/python2.7/dist-packages/duplicity/gpginterface.py", line 420, in _attach_fork_exec
    process.thread.start()
  File "/usr/lib/python2.7/threading.py", line 736, in start
    _start_new_thread(self.__bootstrap, ())
error: can't start new thread

The above has nothing to do with this bug report. Perhaps you should post
it to https://bugs.launchpad.net/bugs/1727653

On Mon, Mar 19, 2018 at 2:07 AM, sebastienserre <email address hidden>
wrote:

> Hello
>
> Traceback (most recent call last):
> File "/usr/bin/duplicity", line 1546, in <module>
> with_tempdir(main)
> File "/usr/bin/duplicity", line 1540, in with_tempdir
> fn()
> File "/usr/bin/duplicity", line 1391, in main
> do_backup(action)
> File "/usr/bin/duplicity", line 1468, in do_backup
> restore(col_stats)
> File "/usr/bin/duplicity", line 731, in restore
> restore_get_patched_rop_iter(col_stats)):
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 560, in Write_ROPaths
> for ropath in rop_iter:
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 523, in integrate_patch_iters
> for patch_seq in collated:
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 389, in yield_tuples
> setrorps(overflow, elems)
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 378, in setrorps
> elems[i] = iter_list[i].next()
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 107, in filter_path_iter
> for path in path_iter:
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 121, in difftar2path_iter
> tarinfo_list = [tar_iter.next()]
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 339, in next
> self.set_tarfile()
> File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
> 333, in set_tarfile
> self.current_fp = self.fileobj_iter.next()
> File "/usr/bin/duplicity", line 768, in get_fileobj_iter
> manifest.volume_info_dict[vol_num])
> File "/usr/bin/duplicity", line 811, in restore_get_enc_fileobj
> fileobj = tdp.filtered_open_with_delete("rb")
> File "/usr/lib/python2.7/dist-packages/duplicity/dup_temp.py", line
> 119, in filtered_open_with_delete
> fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
> File "/usr/lib/python2.7/dist-packages/duplicity/path.py", line 778, in
> filtered_open
> return gpg.GPGFile(False, self, gpg_profile)
> File "/usr/lib/python2.7/dist-packages/duplicity/gpg.py", line 202, in
> __init__
> 'logger': self.logger_fp})
> File "/usr/lib/python2.7/dist-packages/duplicity/gpginterface.py", line
> 374, in run
> create_fhs, attach_fhs)
> File "/usr/lib/python2.7/dist-packages/duplicity/gpginterface.py", line
> 420, in _attach_fork_exec
> process.thread.start()
> File "/usr/lib/python2.7/threading.py", line 736, in start
> _start_new_thread(self.__bootstrap, ())
> error: can't start new thread
>
> --
> You received this bug notification because you are subscribed to
> duplicity in Ubuntu.
> https://bugs.launchpad.net/bugs/1729695
>
> Title:
> ASCII decode error, but not due to filenames in backup target
>
> Status in Duplicity:
> Fix Released
> Status in duplicity package in Ubuntu:
> Confirmed
>
> Bug description:
> On Ubuntu 17.10, I have deja-dup 36.2-0ubuntu1 installed. When I run
> "DEJA_DUP_DEBUG=1 deja-dup", it starts a ...

I just installed Windows 10's April 2018 Update, and it looks like it enabled Fast Startup again.

I've got Ubuntu 18.04 now, with duplicity/bionic,now 0.7.17-0ubuntu1 amd64 [installed]. And the bug remains:

Traceback (innermost last):
  File "/usr/bin/duplicity", line 1555, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1541, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1393, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1523, in do_backup
    incremental_backup(sig_chain)
  File "/usr/bin/duplicity", line 668, in incremental_backup
    globals.backend)
  File "/usr/bin/duplicity", line 454, in write_multivol
    (tdp, dest_filename, vol_num)))
  File "/usr/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 146, in schedule_task
    return self.__run_synchronously(fn, params)
  File "/usr/lib/python2.7/dist-packages/duplicity/asyncscheduler.py", line 172, in __run_synchronously
    ret = fn(*params)
  File "/usr/bin/duplicity", line 453, in <lambda>
    vol_num: put(tdp, dest_filename, vol_num),
  File "/usr/bin/duplicity", line 342, in put
    backend.put(tdp, dest_filename)
  File "/usr/lib/python2.7/dist-packages/duplicity/backend.py", line 395, in inner_retry
    % (n, e.__class__.__name__, util.uexc(e)))
  File "/usr/lib/python2.7/dist-packages/duplicity/util.py", line 79, in uexc
    return ufn(unicode(e).encode('utf-8'))
 UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 37: ordinal not in range(128)