error: can't start new thread

Bug #1727653 reported by Wolf Rogner
132
This bug affects 21 people
Affects Status Importance Assigned to Milestone
Duplicity
Fix Released
Medium
Unassigned
deja-dup (Ubuntu)
Triaged
Critical
Unassigned
duplicity (Ubuntu)
In Progress
Undecided
Unassigned

Bug Description

$ uname -a
Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

duplicity gets started daily via deja-dup automatically.

Every now and then (approx. every third time) I get the following error:

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

Failed with an unknown error.

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

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

Restarting deja-dup manually fixes the problem and the next few days, automatic backup will run correctly until (see above).

ProblemType: Bug
DistroRelease: Ubuntu 17.10
Package: duplicity 0.7.12-1ubuntu1
ProcVersionSignature: Ubuntu 4.13.0-16.19-generic 4.13.4
Uname: Linux 4.13.0-16-generic x86_64
ApportVersion: 2.20.7-0ubuntu3
Architecture: amd64
CurrentDesktop: ubuntu:GNOME
Date: Thu Oct 26 10:49:45 2017
InstallationDate: Installed on 2017-10-20 (5 days ago)
InstallationMedia: Ubuntu 17.10 "Artful Aardvark" - Release amd64 (20171018)
SourcePackage: duplicity
UpgradeStatus: No upgrade log present (probably fresh install)

Revision history for this message
Wolf Rogner (war-rsb) wrote :
Revision history for this message
Wolf Rogner (war-rsb) wrote :

I doubt this being a duplicate:
The error message differs and it only happens when deja-dup starts automatically.
When launched manually, deja-dup and duplicity work fine.

Currently only the first automatic launch after a reboot works. Every other attempt leads to the above mentioned error.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

The first launch after a reboot is one where the memory is less fragmented, and possibly where other tasks have not started, so clean memory access is most likely. The current manifest file reader takes in the full file at one time and breaks it apart in memory. This worked well when there was only volume information present, but the addition of the file-changed list made this operation much more memory intensive (added in 0.7.03). Forking a gpg task takes a good bit of memory and the error message sounds generic, so I'm inclined to lean towards memory issues.

To play it safe, I will change the status and leave this note that I'm sure it's related to:
https://bugs.launchpad.net/bugs/1720159

Changed in duplicity (Ubuntu):
assignee: nobody → Kenneth Loafman (kenneth-loafman)
status: New → In Progress
Revision history for this message
Wolf Rogner (war-rsb) wrote :

Please read my comment again:

Only when autostarted the error occurs. When launched manually (the memory situation is the same) it works.

And: I have 16 GB RAM on this machine. I think there will be some contiguous memory available.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote : Re: [Bug 1727653] Re: duplicity fails with unknown error
Download full text (4.4 KiB)

How many open files allowed ("ulimit -n")? Other than memory, "too many
open files" has been the culprit that keeps fork from working.

On Sat, Oct 28, 2017 at 1:10 PM, Wolf Rogner <email address hidden> wrote:

> Please read my comment again:
>
> Only when autostarted the error occurs. When launched manually (the
> memory situation is the same) it works.
>
> And: I have 16 GB RAM on this machine. I think there will be some
> contiguous memory available.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> duplicity fails with unknown error
>
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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,
> i...

Read more...

Revision history for this message
Wolf Rogner (war-rsb) wrote : Re: duplicity fails with unknown error

ulimit -n -> 1024 (default install)

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

You probably want to increase that. It's an extremely low limit. Search for "ubuntu increase max files limit" and you will find answers. Don't be miserly, set it at 32K or 64K.

summary: - duplicity fails with unknown error
+ error: can't start new thread
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

If you could, please test the latest bzr trunk version. I just fixed a major bug that was chewing up a lot of memory. That may help with this problem if the fix above does not work.

Revision history for this message
Václav Haisman (vzeman79) wrote :

Re #8: Is there a PPA for that?

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote : Re: [Bug 1727653] Re: error: can't start new thread
Download full text (4.2 KiB)

Daily duplicity builds -
https://launchpad.net/~duplicity-team/+archive/ubuntu/daily

On Tue, Oct 31, 2017 at 3:52 PM, Václav Haisman <email address hidden> wrote:

> Re #8: Is there a PPA for that?
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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 ...

Read more...

Changed in duplicity:
status: New → In Progress
importance: Undecided → Medium
assignee: nobody → Kenneth Loafman (kenneth-loafman)
Changed in duplicity (Ubuntu):
assignee: Kenneth Loafman (kenneth-loafman) → nobody
Revision history for this message
Václav Haisman (vzeman79) wrote :

I have tested with 0.7.14+bzr1335-0ubuntu3~ubuntu17.10.1 and it still fails the same.

Revision history for this message
Wolf Rogner (war-rsb) wrote :

Tested 0.7.14-bzr1335-0ubuntu3-ubuntu17.10.1 and it produces the following error:

Failed with an unknown error.
Traceback (innermost last):
  File "/usr/bin/duplicity", line 1559, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1545, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1394, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1473, in do_backup
    restore(col_stats)
  File "/usr/bin/duplicity", line 729, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 558, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 521, 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 766, in get_fileobj_iter
    manifest.volume_info_dict[vol_num])
  File "/usr/bin/duplicity", line 809, in restore_get_enc_fileobj
    fileobj = tdp.filtered_open_with_delete("rb")
  File "/usr/lib/python2.7/dist-packages/duplicity/dup_temp.py", line 120, in filtered_open_with_delete
    fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
  File "/usr/lib/python2.7/dist-packages/duplicity/path.py", line 779, in filtered_open
    return gpg.GPGFile(False, self, gpg_profile)
  File "/usr/lib/python2.7/dist-packages/duplicity/gpg.py", line 224, 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

I saw there were 0.7.15 and 0.7.16 available already?

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

0.7.15 is coming out soon, .16 down the road. .15 preview is in the daily builds.

Were you able to increase ulimit -n? What setting?

I'm going to need a debug log. Could you run this with -v9 and supply two files,
1) the first 200 lines of the log
2) the last 200 lines of the log

Please attach to the bug report. Munge if needed, bug do not change structure. Thanks!

Revision history for this message
Václav Haisman (vzeman79) wrote :

I have bumped the file limit to 8k from 4k for last night's backup and still got the same error.

I am not sure how to run this in verbose mode. I am using it through deja-dup and its plugin that runs the backup every night.

What confuses me are the hanging gpg processes that I have reported about in https://bugs.launchpad.net/ubuntu/+source/duplicity/+bug/1728720. Why would that be happening?

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (4.8 KiB)

Do you have a passphrase on the backup? I don't see any key use, and it
looks like gpg-agent is turned off.

On the gpg processes, could you run an strace and see what fd it is hanging
on? "strace -p <pid>" should do it.

You can get a debug trace by doing: DEJA_DUP_DEBUG=1 deja-dup --backup
from the command line.

On Sat, Nov 4, 2017 at 7:46 AM, Václav Haisman <email address hidden> wrote:

> I have bumped the file limit to 8k from 4k for last night's backup and
> still got the same error.
>
> I am not sure how to run this in verbose mode. I am using it through
> deja-dup and its plugin that runs the backup every night.
>
> What confuses me are the hanging gpg processes that I have reported
> about in
> https://bugs.launchpad.net/ubuntu/+source/duplicity/+bug/1728720. Why
> would that be happening?
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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")
> ...

Read more...

Revision history for this message
Wolf Rogner (war-rsb) wrote :

@Kenneth:

I increased ulimit to 4096 -> same error

Then I wanted to understand how ulimit works:

ulimit influences the shell (bash!).

I can start duplicity via deja-dup from the console -> works
I can start deja-dup from the launcher (GNOME-Shell) and manually trigger backup (from the running application) -> works

If deja-dup is started via automatic mechanism (daily launch) -> error

Concluding:

The issue does not lie within duplicity (well this generates the error) but in the calling mechanism of deja-dup (which must provide duplicity with different environments depending on how it calls duplicity).

If my conclusion is correct:

Changing ulimit will not help locate the problem
Getting debug traces via console commands will not help locate the problem
We are looking in the wrong place

Maybe the issue should be forwarded to the deja-dup developers to see how they call duplicity on auto-backup.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (5.2 KiB)

ulimit is settable system wide, so, at the end of /etc/security/limits.conf
add the lines:

* soft nfile 16384
* hard nfile 32768

then reboot the system. That will set system wide limits for all tasks.

On Sun, Nov 5, 2017 at 4:29 AM, Wolf Rogner <email address hidden> wrote:

> @Kenneth:
>
> I increased ulimit to 4096 -> same error
>
> Then I wanted to understand how ulimit works:
>
> ulimit influences the shell (bash!).
>
>
> I can start duplicity via deja-dup from the console -> works
> I can start deja-dup from the launcher (GNOME-Shell) and manually trigger
> backup (from the running application) -> works
>
> If deja-dup is started via automatic mechanism (daily launch) -> error
>
> Concluding:
>
> The issue does not lie within duplicity (well this generates the error)
> but in the calling mechanism of deja-dup (which must provide duplicity
> with different environments depending on how it calls duplicity).
>
> If my conclusion is correct:
>
> Changing ulimit will not help locate the problem
> Getting debug traces via console commands will not help locate the problem
> We are looking in the wrong place
>
> Maybe the issue should be forwarded to the deja-dup developers to see
> how they call duplicity on auto-backup.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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-p...

Read more...

Revision history for this message
abautu (abautu-gmail) wrote :

From /etc/xdg/autostart/org.gnome.DejaDup.Monitor.desktop (and https://git.launchpad.net/deja-dup/tree/data/org.gnome.DejaDup.Monitor.desktop.in):

# Try to limit memory -- we have reports of runaway deja-dup-monitor processes
# but I can't reproduce it. So until we fix whatever is happening there, try
# this. LP: #1302416
Exec=sh -c "ulimit -v 1000000; ulimit -n 4096; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

In fact, limits file of monitor process (under /proc) shows:
Max open files 1024 1048576 files

Revision history for this message
abautu (abautu-gmail) wrote :

The backup completed succesfully (while running automatically) after I changed in /etc/xdg/autostart/org.gnome.DejaDup.Monitor.desktop from

Exec=sh -c "ulimit -v 1000000; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

to

Exec=sh -c "ulimit -v 1000000; ulimit -n 4096; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

Limits file of process under /proc still shows
Max open files 1024 1048576 files

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

This will work when duplicity is run from DejaDup, not when it is run from the console or from cron.

The system wide solution above will work for all situations.

Revision history for this message
Håkon Enger (hakon-enger) wrote :

Hello,

Today I hit the same problem as in bug #1722454, MemoryError in manifest.py. I am on Ubuntu 17.10 with duplicity 0.7.12-1ubuntu1. I also found a bugreport in Debian that seems to be the same thing: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=881021

Here is my backtrace:

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 1416, in do_backup
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 710, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 836, in get_backup_chains
    add_to_sets(f)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 824, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 101, in add_filename
    self.set_manifest(filename)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 148, in set_manifest
    self.set_files_changed()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 128, in set_files_changed
    mf = self.get_manifest()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 250, in get_manifest
    return self.get_local_manifest()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 224, in get_local_manifest
    return manifest.Manifest().from_string(manifest_buffer)
  File "/usr/lib/python2.7/dist-packages/duplicity/manifest.py", line 207, in from_string
    self.files_changed = list(map(parse_fileinfo, match.group(3).split('\n')))
MemoryError

Revision history for this message
Wolf Rogner (war-rsb) wrote :

Deja-Dup and duplicity seemed to work with kernel 4.13.0-19. After that (21 and 22) the issue reappeared.

Very frustrating.

Workaround: Start Deja-Dup manually after it failed.

Careful: Deja-dup claims that the backup has been carried out even when the above error occurs. In my case, there is no backup on the server (so, no, it did not back up, it might have collected the files).

Merry Christmas

Revision history for this message
Wolf Rogner (war-rsb) wrote :

@Kenneth #17:

I verified that the settings recommended in comment #17 change nothing (several kernel updates later)

a) if anything, it should be nofile and not nfile
b) /etc/security/limits.conf may be altered but any settings there are ignored
c) ulimit is a bash parameter and cannot be applied system-wide.
d) even when called from the command line with as little as soft limit of 1024 (the default) Deja-Dup/duplicity works fine.

@abautu #19:

Nice try, nevertheless, it does not make Deja-Dup work either.

As I mentioned before: It's not a problem of duplicity but of Deja-Dup.

Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in deja-dup (Ubuntu):
status: New → Confirmed
Revision history for this message
Václav Haisman (vzeman79) wrote :
Download full text (4.5 KiB)

So I have several (over 5) processes in the previously mentioned state: Duplicity with a dozen or so gpg processes under it, hanging, duplicity is being run as `usr/bin/duplicity restore`.

I have attached generated a core dump, downloaded symbols and analysed the core dump with GDB. This is the stack trace:

#0 0x00007f6a2a3130c4 in __GI___libc_write (fd=1, buf=buf@entry=0x55af21404900, nbytes=nbytes@entry=4096) at ../sysdeps/unix/sysv/linux/write.c:26
#1 0x00007f6a2a291ba7 in _IO_new_file_write (f=0x7f6a2a5ea720 <_IO_2_1_stdout_>, data=0x55af21404900, n=4096) at fileops.c:1255
#2 0x00007f6a2a293782 in new_do_write (to_do=4096,
    data=0x55af21404900 "**REDACTED**", fp=0x7f6a2a5ea720 <_IO_2_1_stdout_>) at fileops.c:510
#3 _IO_new_do_write (fp=0x7f6a2a5ea720 <_IO_2_1_stdout_>,
    data=0x55af21404900 "**REDACTED**", to_do=4096) at fileops.c:486
#4 0x00007f6a2a2923bd in _IO_new_file_xsputn (f=0x7f6a2a5ea720 <_IO_2_1_stdout_>, data=<optimized out>, n=8192) at fileops.c:1323
#5 0x00007f6a2a28651b in __GI__IO_fwrite (buf=buf@entry=0x55af213d57b0, size=size@entry=1, count=count@entry=8192, fp=0x7f6a2a5ea720 <_IO_2_1_stdout_>) at iofwrite.c:39
#6 0x00007f6a2a5f31ec in func_fp_write (cookie=0x55af213d5730, buffer=0x55af213d57b0, size=8192) at ../../src/estream.c:1523
#7 0x00007f6a2a5f2b18 in flush_stream (stream=stream@entry=0x55af213d5750) at ../../src/estream.c:1965
#8 0x00007f6a2a5f3108 in es_write_fbf (stream=stream@entry=0x55af213d5750,
    buffer=buffer@entry=0x55af213fc8f0 "**REDACTED**", bytes_to_write=bytes_to_write@entry=32768, bytes_written=bytes_written@entry=0x7fffb74c6d30) at ../../src/estream.c:2711
#9 0x00007f6a2a5f4313 in es_writen (stream=stream@entry=0x55af213d5750, buffer=buffer@entry=0x55af213fc8f0, bytes_to_write=32768, bytes_written=bytes_written@entry=0x7fffb74c6da0)
    at ../../src/estream.c:2813
#10 0x00007f6a2a5f5fac in _gpgrt_fwrite (ptr=ptr@entry=0x55af213fc8f0, size=size@entry=1, nitems=nitems@entry=32768, stream=0x55af213d5750) at ../../src/estream.c:4221
#11 0x00007f6a2a5fae35 in gpgrt_fwrite (ptr=ptr@entry=0x55af213fc8f0, size=size@entry=1, nitems=nitems@entry=32768, stream=<optimized out>) at ../../src/visibility.c:466
#12 0x000055af1f4b53a2 in handle_plaintext (pt=pt@entry=0x55af213dbbb0, mfx=mfx@entry=0x55af213efcd0, nooutput=<optimized out>, clearsig=clearsig@entry=0) at ../../g10/plaintext.c:426
#13 0x000055af1f4a0ddc in proc_plaintext (c=c@entry=0x55af213efcb0, pkt=pkt@entry=0x55af213efd60) at ../../g10/mainproc.c:760
#14 0x000055af1f4a3d7b in do_proc_packets (ctrl=0x55af213dbb30, c=0x55af213efcb0, a=0x55af213e72a0) at ../../g10/mainproc.c:1412
#15 0x000055af1f4a3f0a in proc_packets (ctrl=ctrl@entry=0x55af213dbb30, anchor=anchor@entry=0x55af213edaf0, a=0x55af213e72a0) at ../../g10/mainproc.c:1181
#16 0x000055af1f492aaf in handle_compressed (ctrl=0x55af213dbb30, procctx=procctx@entry=0x55af213edaf0, cd=0x55af213edba0, callback=callback@entry=0x0, passthru=passthru@entry=0x0)
    at ../../g10/compress.c:324
#17 0x000055af1f4a1070 in proc_compressed (c=c@entry=0x55af213edaf0, pkt=pkt@entry=0x55af213dcd90) at ../../g10/mainproc.c:819
#18 0x000055af1f4a3c9b in do_proc_packets (ctrl=0x55af213dbb30, c=0...

Read more...

Revision history for this message
Václav Haisman (vzeman79) wrote :

Debugging the Python process of Duplicity shows no polling or reading from appropriate number of pipes:

* 1 Thread 0x7f7f510d0740 (LWP 19797) 0x00007f7f50ce9f96 in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=0, futex_word=0x559f3d5e48f0)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:205
  2 Thread 0x7f7f4d9b0700 (LWP 19801) 0x00007f7f50a01951 in __GI___poll (fds=0x559f3d517d30, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
  3 Thread 0x7f7f469fd700 (LWP 19802) 0x00007f7f50a01951 in __GI___poll (fds=0x559f3d5290a0, nfds=3, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
  4 Thread 0x7f7f461fc700 (LWP 19960) 0x00007f7f50ceba4a in __waitpid (pid=19959, stat_loc=0x7f7f461fb534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  5 Thread 0x7f7f3ffff700 (LWP 19962) 0x00007f7f50ceba4a in __waitpid (pid=19961, stat_loc=0x7f7f3fffe534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  6 Thread 0x7f7f3f7fe700 (LWP 19965) 0x00007f7f50ceba4a in __waitpid (pid=19964, stat_loc=0x7f7f3f7fd534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  7 Thread 0x7f7f3effd700 (LWP 19967) 0x00007f7f50ceba4a in __waitpid (pid=19966, stat_loc=0x7f7f3effc534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  8 Thread 0x7f7f3e7fc700 (LWP 19969) 0x00007f7f50ceba4a in __waitpid (pid=19968, stat_loc=0x7f7f3e7fb534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  9 Thread 0x7f7f3dffb700 (LWP 19971) 0x00007f7f50ceba4a in __waitpid (pid=19970, stat_loc=0x7f7f3dffa534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  10 Thread 0x7f7f3d7fa700 (LWP 19973) 0x00007f7f50ceba4a in __waitpid (pid=19972, stat_loc=0x7f7f3d7f9534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  11 Thread 0x7f7f3cff9700 (LWP 19975) 0x00007f7f50ceba4a in __waitpid (pid=19974, stat_loc=0x7f7f3cff8534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  12 Thread 0x7f7f2bfff700 (LWP 19977) 0x00007f7f50ceba4a in __waitpid (pid=19976, stat_loc=0x7f7f2bffe534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  13 Thread 0x7f7f2b7fe700 (LWP 19979) 0x00007f7f50ceba4a in __waitpid (pid=19978, stat_loc=0x7f7f2b7fd534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  14 Thread 0x7f7f2affd700 (LWP 19981) 0x00007f7f50ceba4a in __waitpid (pid=19980, stat_loc=0x7f7f2affc534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  15 Thread 0x7f7f2a7fc700 (LWP 19983) 0x00007f7f50ceba4a in __waitpid (pid=19982, stat_loc=0x7f7f2a7fb534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  16 Thread 0x7f7f29ffb700 (LWP 19985) 0x00007f7f50ceba4a in __waitpid (pid=19984, stat_loc=0x7f7f29ffa534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  17 Thread 0x7f7f297fa700 (LWP 19988) 0x00007f7f50ceba4a in __waitpid (pid=19987, stat_loc=0x7f7f297f9534, options=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

I think this is a duplicate of https://bugs.launchpad.net/ubuntu/+source/duplicity/+bug/1730451 and that you've just run out of memory for a new thread. Please upgrade to the newest version and try again.

There are three options:

* Release tarball Install - https://launchpad.net/duplicity/+download
* Daily duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/daily
* Stable duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/ppa

NOTE: UNinstall duplicity first if it was installed via the distribution repository. For Ubuntu, that would be "sudo apt-get purge duplicity".

Changed in duplicity:
milestone: none → 0.7.17
Revision history for this message
Václav Haisman (vzeman79) wrote :

@Kenneth: The call stack is clearly different. Also, it does not explain the hanging threads in Duplicity and processes of GPG waiting on pipe write to return. Also, I have been running the PPA version last few months.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (4.5 KiB)

Whoops! You are correct. I thought you were on 0.7.10 from a previous
message.

OK, what I need to see is:
 - A debug run (-v9) with the first 200 lines and the last 200 lines,
 - OS version, Python version, memory size.

On Mon, Jan 22, 2018 at 11:01 AM, Václav Haisman <email address hidden> wrote:

> @Kenneth: The call stack is clearly different. Also, it does not explain
> the hanging threads in Duplicity and processes of GPG waiting on pipe
> write to return. Also, I have been running the PPA version last few
> months.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in deja-dup package in Ubuntu:
> Confirmed
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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/pa...

Read more...

Revision history for this message
Václav Haisman (vzeman79) wrote :

So, I have been experimenting. I have removed ulimit -v 100...0 out of the command line because I have unlimited limit by default. What I have added though is ulimit -s 16384 which doubles stack limit and I have also ulimit -n 2048 to double file limit. Todays backup passed without the usual exception.

I suggest others do the same. Find out file handle limits and stack size limits and try again with doubled values. And remove the VM limit if it actually sets a limit from unlimited.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (4.8 KiB)

Thanks for catching that. Was the system installed with those limits, or
had you put them in earlier? I've never seen a distro that tried to limit
virtual memory.

On Wed, Jan 24, 2018 at 12:40 AM, Václav Haisman <email address hidden> wrote:

> So, I have been experimenting. I have removed ulimit -v 100...0 out of
> the command line because I have unlimited limit by default. What I have
> added though is ulimit -s 16384 which doubles stack limit and I have
> also ulimit -n 2048 to double file limit. Todays backup passed without
> the usual exception.
>
> I suggest others do the same. Find out file handle limits and stack size
> limits and try again with doubled values. And remove the VM limit if it
> actually sets a limit from unlimited.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in deja-dup package in Ubuntu:
> Confirmed
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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 "/u...

Read more...

Revision history for this message
Václav Haisman (vzeman79) wrote :

@Kenneth: The -v limit was suggested in comment #19.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

That does explain why you can't open more gpg threads. Each instance of gpg will take several file handles and eats more resources.

I'm going to leave this open for now. Perhaps duplicity should put out a warning after this error telling people to increase their num-files limits, or something similar.

Revision history for this message
Wolf Rogner (war-rsb) wrote :

I cannot confirm that ulimit -s 16384 will heal the issue (suggested in #30). I have inserted ulimit -s 16384 to no avail.

Exec=sh -c "ulimit -v 1000000; ulimit -s 16384; ulimit -n 4096; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

-> still causes the issue.

Trying to check my file count I realized that Nautilus interupts file count and restarts regularly. This behaviour might be triggered by several symlinks.

Can it be that duplicity tries to follow a directory structure and gets confused if circular references via symlinks exist?

If so, I have to draw a link tree for further analysis.

Revision history for this message
Václav Haisman (vzeman79) wrote :

On 26 January 2018 at 11:59, Wolf Rogner wrote:
> I cannot confirm that ulimit -s 16384 will heal the issue (suggested in
> #30). I have inserted ulimit -s 16384 to no avail.
>
> Exec=sh -c "ulimit -v 1000000; ulimit -s 16384; ulimit -n 4096; exec
> /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

Can you try without the ulimit -v 1000000?

Have you killed the existing deja-dup-monitor process first?

What's your ulimit -a output?

>
> -> still causes the issue.
>
> Trying to check my file count I realized that Nautilus interupts file
> count and restarts regularly. This behaviour might be triggered by
> several symlinks.
>
> Can it be that duplicity tries to follow a directory structure and gets
> confused if circular references via symlinks exist?
>
> If so, I have to draw a link tree for further analysis.
>

Revision history for this message
Wolf Rogner (war-rsb) wrote :

Sorry for the delay, I wanted to make sure my answer is accurate.

I have three machines set up with 17.10 afresh.
mbpr13a 8GB, 4.13.0-25-generic
mbpr15a 16GB, 4.13.0-25-generic
mbpr13b 16GB, 4.13.0-32-generic

mbpr15a does backups ooB
mbpr13a/b have the reported issue

The original line in /etc/xdg/autostart/org.gnome.DejaDup.Monitor.desktop

Exec=sh -c "ulimit -v 1000000; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

leads to the issue

Setting ulimit -n or ulimit -s additionally does not remedy the error

This line worked

Exec=sh -c "ulimit -s 16384; ulimit -n 4096; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

@Vaclav #35: I always test after reboot and consequently after suspend to RAM.
The solution works under those conditions.

What irritates my: mbpr15a works with the original line. ???

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (5.1 KiB)

It's probably the -n option (number of open files). The default is 1024
and that's way too low.

On Sun, Jan 28, 2018 at 4:07 AM, Wolf Rogner <email address hidden> wrote:

> Sorry for the delay, I wanted to make sure my answer is accurate.
>
> I have three machines set up with 17.10 afresh.
> mbpr13a 8GB, 4.13.0-25-generic
> mbpr15a 16GB, 4.13.0-25-generic
> mbpr13b 16GB, 4.13.0-32-generic
>
> mbpr15a does backups ooB
> mbpr13a/b have the reported issue
>
> The original line in
> /etc/xdg/autostart/org.gnome.DejaDup.Monitor.desktop
>
> Exec=sh -c "ulimit -v 1000000; exec /usr/lib/x86_64-linux-gnu/deja-dup
> /deja-dup-monitor"
>
> leads to the issue
>
> Setting ulimit -n or ulimit -s additionally does not remedy the error
>
> This line worked
>
> Exec=sh -c "ulimit -s 16384; ulimit -n 4096; exec /usr/lib/x86_64-linux-
> gnu/deja-dup/deja-dup-monitor"
>
> @Vaclav #35: I always test after reboot and consequently after suspend to
> RAM.
> The solution works under those conditions.
>
> What irritates my: mbpr15a works with the original line. ???
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in deja-dup package in Ubuntu:
> Confirmed
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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_ta...

Read more...

Revision history for this message
Wolf Rogner (war-rsb) wrote :

Just adding -n 4096 or -s 16384 alone or in combination does not do the trick.

Only adding these two PLUS removing -v 1000000 works.

This and the fact that on my mbpr15a the original line works fine confuses me.

Revision history for this message
Vej (vej) wrote :

This seems to be a regression introduced by a fix for bug #1302416.

Changed in deja-dup (Ubuntu):
status: Confirmed → Triaged
importance: Undecided → Critical
tags: added: regression-release
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

Please upgrade to the current version of duplicity, 0.7.16. This will assure that any bugs fixed since your release are available and may fix your issue. This applies especially to duplicity versions between 0.7.03 and 0.7.14 inclusive. There was a fix in 0.7.15 that reduced memory usage drastically, and will help with memory errors and inability to start new threads.

The bug that was resolved in 0.7.15:
* Fixed bug #1720159 - Cannot allocate memory with large manifest file since 0.7.03
  - filelist is not read if --file-changed option in collection-status not present
  - This will keep memory usage lower in non collection-status operations

There are three options:

* Release tarball Install - https://launchpad.net/duplicity/+download
* Daily duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/daily
* Stable duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/ppa

NOTE: UNinstall duplicity first if it was installed via the distribution repository. For Ubuntu, that would be "sudo apt-get purge duplicity".

Revision history for this message
Michael Terry (mterry) wrote :

I'd also be curious if this is because of duplicity <0.7.16 or because of the ulimit line we use for deja-dup-monitor. It's not clear to me if I should change the ulimit line or if we just need to update duplicity for those users affected.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (5.0 KiB)

I would bet the update will fix it. Huge manifests go into memory, in
bulk, and in lists. The lists stay around and if Python GC is not working
properly, the bulk reads do as well. During processing, there were as many
as 3 copies of the manifest in memory, one bulk, one the result of re
iteration, and the other in the collection list. That kind of misuse can
really screw up GC.

As answer to your question, changing to 'ulimit -n 10240' could help in a
very cases, but I would try both individually to see which one does the job.

If they are still on the 0.6-series, the 'ulimit' fix is the only one that
would work.

On Sun, Feb 11, 2018 at 12:34 PM, Michael Terry <email address hidden> wrote:

> I'd also be curious if this is because of duplicity <0.7.16 or because
> of the ulimit line we use for deja-dup-monitor. It's not clear to me if
> I should change the ulimit line or if we just need to update duplicity
> for those users affected.
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> In Progress
> Status in deja-dup package in Ubuntu:
> Triaged
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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 ...

Read more...

Changed in duplicity:
milestone: 0.7.17 → none
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

I think this is fixed in the latest releases, however, the OPs are not responding and I have no test case to run against. Marking this incomplete until someone can confirm that it does not work on 0.7.17 and later.

Changed in duplicity:
assignee: Kenneth Loafman (kenneth-loafman) → nobody
status: In Progress → Incomplete
Revision history for this message
Miles (milesbeck) wrote :

I'm also seeing this issue and I just purged Duplicity and then added it back with the PPA and I am still seeing the issue. I am using 0.7.17 now. What information can I provide to help fix this?

Ubuntu Version: UbuntuMate 17.10

uname -a
Linux 4.13.0-36-generic #40-Ubuntu SMP Fri Feb 16 20:07:48 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

ulimit -v
unlimited

ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 31429
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 31429
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :
Download full text (5.5 KiB)

Try upping your ulimit on num files from 1024 to 8192 or higher.

To do this for duplicity, run like so:
$ ulimit -n 8192
$ duplicity ...

To set this system wide see:
https://www.google.com/search?q=linux+increase+number+of+open+files&oq=linux+increase+num&aqs=chrome.0.0j69i57j0l4.12567j0j7&sourceid=chrome&ie=UTF-8

On Tue, Mar 6, 2018 at 9:06 PM, Miles <email address hidden> wrote:

> I'm also seeing this issue and I just purged Duplicity and then added it
> back with the PPA and I am still seeing the issue. I am using 0.7.17
> now. What information can I provide to help fix this?
>
> Ubuntu Version: UbuntuMate 17.10
>
> uname -a
> Linux 4.13.0-36-generic #40-Ubuntu SMP Fri Feb 16 20:07:48 UTC 2018 x86_64
> x86_64 x86_64 GNU/Linux
>
> ulimit -v
> unlimited
>
> ulimit -a
> core file size (blocks, -c) 0
> data seg size (kbytes, -d) unlimited
> scheduling priority (-e) 0
> file size (blocks, -f) unlimited
> pending signals (-i) 31429
> max locked memory (kbytes, -l) 64
> max memory size (kbytes, -m) unlimited
> open files (-n) 1024
> pipe size (512 bytes, -p) 8
> POSIX message queues (bytes, -q) 819200
> real-time priority (-r) 0
> stack size (kbytes, -s) 8192
> cpu time (seconds, -t) unlimited
> max user processes (-u) 31429
> virtual memory (kbytes, -v) unlimited
> file locks (-x) unlimited
>
> --
> You received this bug notification because you are subscribed to
> duplicity in Ubuntu.
> https://bugs.launchpad.net/bugs/1727653
>
> Title:
> error: can't start new thread
>
> Status in Duplicity:
> Incomplete
> Status in deja-dup package in Ubuntu:
> Triaged
> Status in duplicity package in Ubuntu:
> In Progress
>
> Bug description:
> $ uname -a
> Linux mbpr13b 4.13.0-16-generic #19-Ubuntu SMP Wed Oct 11 18:35:14 UTC
> 2017 x86_64 x86_64 x86_64 GNU/Linux
>
> duplicity gets started daily via deja-dup automatically.
>
> Every now and then (approx. every third time) I get the following
> error:
>
> ------------------
>
> Failed with an unknown error.
>
> 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()
> F...

Read more...

Revision history for this message
Miles (milesbeck) wrote :

I'm unable to increase the ulimit on my system. I've added the new size in limits.conf but that does not help. Running the command manually gives me a permissions error with files open. At this point the upgrade to 0.7.17 did not help so it appears something else need to be look at.

Changed in duplicity:
status: Incomplete → Confirmed
assignee: nobody → Kenneth Loafman (kenneth-loafman)
assignee: Kenneth Loafman (kenneth-loafman) → nobody
assignee: nobody → Kenneth Loafman (kenneth-loafman)
status: Confirmed → In Progress
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

It's odd you would get an error on 'ulimit -n 8192'.

Do it again and paste in the full error message.

As to limits.conf, did you logout and log back in?

Do a 'ulimit -a' paste that in as well.

Revision history for this message
Miles (milesbeck) wrote :

~$ ulimit -n 8192
bash: ulimit: open files: cannot modify limit: Operation not permitted

~$ ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 31429
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 31429
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

I did log out when initially adding to limits.conf. I've also rebooted a few times since this was added.

At the end of the limits.conf I have the following:

#@student hard nproc 20
#@faculty soft nproc 20
#@faculty hard nproc 50
#ftp hard nproc 0
#ftp - chroot /ftp
#@student - maxlogins 4
* soft nofile 10240
* hard nofile 10240
# End of file

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

See this: https://superuser.com/a/1200818

Let me know if it works.

Revision history for this message
Miles (milesbeck) wrote :
Download full text (3.3 KiB)

I was able to get the open files changed to 65535 using the above link. Today after I started my computer I got the same error I've been getting about not being able to create a new thread.

~$ ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 31429
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 65535
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 31429
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

Error I see when the backup runs automatically.

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 1472, in do_backup
    restore(col_stats)
  File "/usr/bin/duplicity", line 728, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 558, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 521, 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 765, in get_fileobj_iter
    manifest.volume_info_dict[vol_num])
  File "/usr/bin/duplicity", line 808, in restore_get_enc_fileobj
    fileobj = tdp.filtered_open_with_delete("rb")
  File "/usr/lib/python2.7/dist-packages/duplicity/dup_temp.py", line 120, in filtered_open_with_delete
    fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
  File "/usr/lib/python2.7/dist-packages/duplicity/path.py", line 779, in filtered_open
    return gpg.GPGFile(False, self, gpg_profile)
  File "/usr/lib/python2.7/dist-packages/duplicity/gpg.py", line 224, 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
    ...

Read more...

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

A few more requests then:

What command are you running? Full command line please.

How much memory do you have available to duplicity?

Is it being run under Deja-Dup, cron, or command line?

Revision history for this message
Miles (milesbeck) wrote :

>A few more requests then:

>What command are you running? Full command line please.

This is running through deja-dup on start-up. The command that it's using is:
sh -c "ulimit -v 1000000; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

>How much memory do you have available to duplicity?
Not sure if this is what you want but this is what 'free -m' shows.
free -m
              total used free shared buff/cache available
Mem: 7912 4373 415 145 3123 4241
Swap: 8127 0 8127

>Is it being run under Deja-Dup, cron, or command line?

Deja-Dup

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

Try this then:

sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

It adds the ulimit -n call and may do what you need now that the systemd settings are in place.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

Try running the command as:

DEJA_DUP_DEBUG=1 sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu
/deja-dup/deja-dup-monitor"

This will create a large debug log in ~/.cache/deja-dup/. Please add that as an attachment to this bug report.

Revision history for this message
Miles (milesbeck) wrote :

>Try this then:

>sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu/deja-dup/deja-dup-monitor"

>It adds the ulimit -n call and may do what you need now that the systemd settings are in place.

I added this and the backup did not start automatically yesterday so I tried to run it manually and am getting the permission error again:

~$ sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu
/deja-dup/deja-dup-monitor"
sh: 1: exec: /usr/lib/x86_64-linux-gnu: Permission denied

>Try running the command as:

>DEJA_DUP_DEBUG=1 sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu
/deja-dup/deja-dup-monitor"

>This will create a large debug log in ~/.cache/deja-dup/. Please add that as an attachment to this bug report.

The above command also gives me a permission error:

~$ DEJA_DUP_DEBUG=1 sh -c "ulimit -v 1000000; ulimit -n 8192; exec /usr/lib/x86_64-linux-gnu
/deja-dup/deja-dup-monitor"
sh: 1: exec: /usr/lib/x86_64-linux-gnu: Permission denied

Trying the same command without the 'ulimit -n 8182' also gives me a permission error:

~$ DEJA_DUP_DEBUG=1 sh -c "ulimit -v 1000000; exec /usr/lib/x86_64-linux-gnu
/deja-dup/deja-dup-monitor"
sh: 1: exec: /usr/lib/x86_64-linux-gnu: Permission denied

I'm not sure what's going on now. I was getting permission errors as shown above. I tried the commands using 'su' and that did not help either. Then I tried taking my original command that would auto-start the backup and that did not error but also did not start anything. Then I tried all the commands above with the logging and that did not give the permission but it also did not create a log that I can find.

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

From the permissions error message it looks like you tried to run that as yourself. Try going into root and running the commands again.

Changed in duplicity:
milestone: none → 0.7.18
Changed in duplicity:
milestone: 0.7.18 → none
assignee: Kenneth Loafman (kenneth-loafman) → nobody
Changed in duplicity:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.