Back In Time

encrypted remote backup hangs on "start 'encfsctl encode' process"

Bug #1455925 reported by Akki
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Back In Time
Fix Released
Critical
Germar
Back In Time 1.1.6

Bug Description

Hi there,

I've installed backintime 1.1.4 from sources on opensuse 13.2.

Local backups (unencrypted & encrypted) and unencrypted remote backups work fine. Encrypted remote backups, however, "hang" on "start 'encfsctl encode' process". (Other actions, like snapshots-list, do work fine with same settings.)

Console output (slightly anonymized) is limited:

akki@system:~> backintime --profile-id 1 --backup

Back In Time
Version: 1.1.4

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.

INFO: Lock
WARNING: Inhibit Suspend failed.
INFO: mount ssh_encfs: user@remotehost:/files/test on /home/akki/.local/share/backintime/mnt/D5543F05/mountpoint
INFO: mount ssh_encfs: / on /home/akki/.local/share/backintime/mnt/5839A9F8/mountpoint
INFO: mount ssh_encfs: /home/akki/.local/share/backintime/mnt/D5543F05/mountpoint on /home/akki/.local/share/backintime/mnt/E10EF3D9/mountpoint
INFO: on process begins
INFO: Profile_id: 1
INFO: start 'encfsctl encode' process
INFO: [qt4systrayicon] begin loop

Processes at this time:

akki@system:~> ps -ef | grep backintime
root 2095 1 0 15:57 ? 00:00:00 /usr/bin/python3 /usr/share/backintime/qt4/serviceHelper.py
akki 2142 1 0 15:57 ? 00:00:00 python3 /usr/share/backintime/common/backintime.py --pw-cache start
akki 4234 2178 0 16:20 pts/0 00:00:00 /bin/sh /usr/bin/backintime --profile-id 1 --backup
akki 4235 4234 0 16:20 pts/0 00:00:00 python3 /usr/share/backintime/common/backintime.py --profile-id 1 --backup
akki 4236 4235 0 16:20 ? 00:00:00 ssh-agent python3 /usr/share/backintime/common/backintime.py --profile-id 1 --backup
akki 4261 1 0 16:20 ? 00:00:00 sshfs -p 22 -o ServerAliveInterval=240 -o idmap=user user@remotehost:/files/test /home/akki/.local/share/backintime/mnt/D5543F05/mountpoint
akki 4274 1 0 16:20 ? 00:00:00 encfs --extpass=backintime-askpass --reverse / /home/akki/.local/share/backintime/mnt/5839A9F8/mountpoint
akki 4287 1 0 16:20 ? 00:00:00 encfs --extpass=backintime-askpass /home/akki/.local/share/backintime/mnt/D5543F05/mountpoint /home/akki/.local/share/backintime/mnt/E10EF3D9/mountpoint
akki 4290 4235 0 16:20 pts/0 00:00:01 /usr/bin/python3 /usr/share/backintime/qt4/qt4systrayicon.py 1
akki 4293 4235 0 16:20 pts/0 00:00:00 encfsctl encode --extpass=backintime-askpass /
akki 4348 2392 0 16:26 pts/1 00:00:00 grep --color=auto backintime

Terminating encfsctl process

akki@system:~> kill -s term 4293

results in:

INFO: [qt4systrayicon] begin loop
INFO: Call rsync to take the snapshot
INFO: Command "rsync -rtDHh --links --no-p --no-g --no-o --info=progress2 --no-i-r --rsh="ssh -p 22 " --delete --delete-excluded -v --chmod=Du+wx --exclude="/" --exclude="/" --exclude="" --include="//" --exclude="" --exclude="*" --exclude="/*" --exclude="/" --include="/" --exclude="*" /home/akki/.local/share/backintime/mnt/5839A9F8/mountpoint/ 'user@remotehost:"/files/test/"' 2>&1" returns 0
INFO: Save config file
cp: reguläre Datei „/home/akki/.local/share/backintime/mnt/1_4235/backintime/op-laptop-esprimo.op-net/akki/1/new_snapshot/backup/../config“ kann nicht angelegt werden: Datei oder Verzeichnis nicht gefunden
WARNING: Command "cp "/home/akki/.config/backintime/config" "/home/akki/.local/share/backintime/mnt/1_4235/backintime/op-laptop-esprimo.op-net/akki/1/new_snapshot/backup/.."" returns 256
INFO: Save permissions
Traceback (most recent call last):
  File "/usr/share/backintime/common/backintime.py", line 436, in <module>
    start_app()
  File "/usr/share/backintime/common/backintime.py", line 191, in start_app
    ret = take_snapshot( cfg, True )
  File "/usr/share/backintime/common/backintime.py", line 52, in take_snapshot
    ret = snapshots.Snapshots( cfg ).take_snapshot( force )
  File "/usr/share/backintime/common/snapshots.py", line 916, in take_snapshot
    ret_val, ret_error = self._take_snapshot( snapshot_id, now, include_folders )
  File "/usr/share/backintime/common/snapshots.py", line 1279, in _take_snapshot
    with bz2.BZ2File( self.get_snapshot_fileinfo_path( new_snapshot_id ), 'wb' ) as fileinfo:
  File "/usr/lib64/python3.4/bz2.py", line 102, in __init__
    self._fp = _builtin_open(filename, mode)
FileNotFoundError: [Errno 2] No such file or directory: '/home/akki/.local/share/backintime/mnt/1_4235/backintime/op-laptop-esprimo.op-net/akki/1/new_snapshot/fileinfo.bz2'
INFO: stop 'encfsctl encode' process
Exception ignored in: <bound method Encode.__del__ of <encfstools.Encode object at 0x7f81034a1748>>
Traceback (most recent call last):
  File "/usr/share/backintime/common/encfstools.py", line 325, in __del__
  File "/usr/share/backintime/common/encfstools.py", line 409, in close
  File "/usr/lib64/python3.4/subprocess.py", line 959, in communicate
  File "/usr/lib64/python3.4/subprocess.py", line 1578, in _communicate
BrokenPipeError: [Errno 32] Broken pipe
INFO: [qt4systrayicon] end loop

Snapshot log:

========== Take snapshot (profile 1): Sun May 17 16:20:30 2015 ==========

[I] …
[I] Snapshot erstellen
[I] rsync -rtDHh --links --no-p --no-g --no-o --info=progress2 --no-i-r --rsh="ssh -p 622 " --delete --delete-excluded -v --chmod=Du+wx --exclude="/" --exclude="/" --exclude="" --include="//" --exclude="" --exclude="*" --exclude="/*" --exclude="/" --include="/" --exclude="*" /home/akki/.local/share/backintime/mnt/5839A9F8/mountpoint/ 'user@remotehost:"/files/test/"'
[I] Snapshot erstellen (rsync: building file list ... done)
[I] Snapshot erstellen (rsync: ./)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/V-2Y1swF4,SyzJVZ-MKIjyZl4p3rUMXYnjBz4YGjUzBkj-/N-kYcDrFMqDEuIij4hxH4jBK/Y5NoP1ZSQHJZYuNTpLh0CM4a/LJl,FEXvJinur33x,2sgZm-Y/wsu5QQmAQJV,sqw5pITgck5u/)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/V-2Y1swF4,SyzJVZ-MKIjyZl4p3rUMXYnjBz4YGjUzBkj-/N-kYcDrFMqDEuIij4hxH4jBK/Y5NoP1ZSQHJZYuNTpLh0CM4a/LJl,FEXvJinur33x,2sgZm-Y/)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/V-2Y1swF4,SyzJVZ-MKIjyZl4p3rUMXYnjBz4YGjUzBkj-/N-kYcDrFMqDEuIij4hxH4jBK/Y5NoP1ZSQHJZYuNTpLh0CM4a/)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/V-2Y1swF4,SyzJVZ-MKIjyZl4p3rUMXYnjBz4YGjUzBkj-/N-kYcDrFMqDEuIij4hxH4jBK/)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/V-2Y1swF4,SyzJVZ-MKIjyZl4p3rUMXYnjBz4YGjUzBkj-/)
[I] Snapshot erstellen (rsync: deleting i4wE1MYRGf8Q8oaLZY1tHsea/)
[I] Snapshot erstellen (rsync: deleting .encfs6.xml)
[I] Snapshot erstellen (rsync: sent 41 bytes received 692 bytes 488.67 bytes/sec)
[I] Snapshot erstellen (rsync: total size is 0 speedup is 0.00)
[I] Einstellungen speichern …
[I] Zugriffsrechte speichern …

(After that, the backup directory is completely empty; all prior snapshots and encfs configuration file are deleted.)

Unfortunately, I can't find any error message or other output of encfsctl in my log files. Any ideas?

Thanks,
Akki

Revision history for this message
Germar (germar) wrote :

URGS. That's really bad, that BIT will use empty in/exclude patterns and dst after encfsctl was terminated! Sorry for that! I hope this was only test files?

Which encfs version do you use?

Changed in backintime:
importance: Undecided → Critical
assignee: nobody → Germar (germar)
milestone: none → 1.1.6
Revision history for this message
Akki (akki.42) wrote :

Hi Germar,

Thanks for your concern. No worries, the above log is from a test account. ;-)

My encfs version is 1.7.4.

Best regards,
Akki

Germar (germar)
Changed in backintime:
status: New → Triaged
Revision history for this message
Germar (germar) wrote :

I installed OpenSuse in Virtalbox and was able to confirm this.

Did you manage to find a package for python3-keyring on OpenSuse? There is python-keyring but nothing for python3.

When you create new SSH-encrypted profile does it ask you to confirm the password for encryption in a dialog or on commandline?

Revision history for this message
Akki (akki.42) wrote :

Thanks for your efforts.

Will check python3-keyring and pw confirmation dialog next weekend (once back from vacation).

Revision history for this message
Akki (akki.42) wrote :

PS: just checked on http://software.opensuse.org/package/python3-keyring :
I'm pretty sure I added python3 development repository ( http://download.opensuse.org/repositories/devel:/languages:/python3/openSUSE_13.2/ ) and installed python3-keyring from there...

Revision history for this message
Germar (germar) wrote :

Jepp, that did the trick. Thanks. Didn't use Suse for ~15 years :D

Revision history for this message
Akki (akki.42) wrote :

Just a short confirmation:

I did indeed install python3-keyring from the aforementioned python3 development repository.

And: confirmation of encryption password for new ssh-encrypted profiles is in a dialog window (not on command line).

Best regards,
Akki

Germar (germar)
Changed in backintime:
status: Triaged → Fix Committed
Revision history for this message
Germar (germar) wrote :

This was caused by wrong bufsize settings while calling 'encfsctl encode'.

I also added an exception which will terminate BackInTime if the encode function returns an empty string (e.g. because encfsctl was killed) to avoid deleting the whole snapshot path again.

Revision history for this message
Akki (akki.42) wrote :

backintime 1.1.5 / trunk has just successfully completed a backup on my machine...

Thus: many many thanks for your support and bit development!

Germar (germar)
Changed in backintime:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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