Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

os.access(dirname, os.W_OK) does not recognize unwriteable folders in Snapshot.delete_path.handle_error #490

Closed
colinl opened this issue Nov 10, 2015 · 18 comments
Milestone

Comments

@colinl
Copy link

colinl commented Nov 10, 2015

I am a new user so apologies if this is operator error.
Using Ubuntu 15.10 with BIT 1.1.8 from stable ppa and gnome UI or command line I am unable to delete a snapshot. From the UI I click Snapshots icon, select the one to be remove and click Delete and it just returns immediately to the snapshots dialog with no sign that anything is happening. The display is not greyed and even though I left it 30 minutes the snapshot was not deleted.

From the command line I ran

backintime --debug remove

I expected this to prompt for which one to delete but I see

DEBUG: [common/backintime.py:450 arg_parse] Arguments: {'debug': True, 'func': <function remove at 0x7fc571a14d08>, 'command': 'remove'} | unknownArgs: []

Back In Time
Version: 1.1.8

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.

DEBUG: [common/backintime.py:496 getConfig] config file: /home/colinl/.config/backintime
DEBUG: [common/backintime.py:497 getConfig] profiles: ['1']
DEBUG: [common/pluginmanager.py:88 PluginManager.load_plugins] Register plugin path /usr/share/backintime/plugins
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin qt4plugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin userscriptsplugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py
DEBUG: [common/sshtools.py:192 SSH.unlock_ssh_agent] Add private key /home/colinl/.ssh/id_rsa to ssh agent
DEBUG: [common/sshtools.py:197 SSH.unlock_ssh_agent] Password available: True
DEBUG: [common/mount.py:298 SSH.mountprocess_lock_acquire] Acquire mountprocess lock /home/colinl/.local/share/backintime/mnt/11889.lock
INFO: [common/mount.py:203 SSH.mount] Mountpoint /home/colinl/.local/share/backintime/mnt/A5868FDC/mountpoint is already mounted
DEBUG: [common/mount.py:319 SSH.set_mount_lock] Set mount lock /home/colinl/.local/share/backintime/mnt/A5868FDC/locks/11889.lock
DEBUG: [common/mount.py:307 SSH.mountprocess_lock_release] Release mountprocess lock /home/colinl/.local/share/backintime/mnt/11889.lock
Do you really want to remove this snapshots?
(no/yes): yes
DEBUG: [common/sshtools.py:244 SSH.unlock_ssh_agent] Private key /home/colinl/.ssh/id_rsa is already unlocked in ssh agent
DEBUG: [common/mount.py:298 SSH.mountprocess_lock_acquire] Acquire mountprocess lock /home/colinl/.local/share/backintime/mnt/11889.lock
DEBUG: [common/mount.py:365 SSH.check_locks] Remove old and invalid lock 11873.lock
INFO: [common/mount.py:232 SSH.umount] Mountpoint /home/colinl/.local/share/backintime/mnt/A5868FDC/mountpoint still in use. Keep mounted
DEBUG: [common/mount.py:337 SSH.del_mount_lock] Remove mount lock /home/colinl/.local/share/backintime/mnt/A5868FDC/locks/11889.lock
DEBUG: [common/mount.py:307 SSH.mountprocess_lock_release] Release mountprocess lock /home/colinl/.local/share/backintime/mnt/11889.lock

If I select a particular one to delete I see

user@tigger:~$ backintime --debug remove 20151110-142002-940
DEBUG: [common/backintime.py:450 arg_parse] Arguments: {'command': 'remove', 'func': <function remove at 0x7fdb00349d08>, 'debug': True} | unknownArgs: []

Back In Time
Version: 1.1.8

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.

DEBUG: [common/backintime.py:496 getConfig] config file: /home/user/.config/backintime
DEBUG: [common/backintime.py:497 getConfig] profiles: ['1']
DEBUG: [common/pluginmanager.py:88 PluginManager.load_plugins] Register plugin path /usr/share/backintime/plugins
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin qt4plugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin userscriptsplugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py
DEBUG: [common/sshtools.py:192 SSH.unlock_ssh_agent] Add private key /home/user/.ssh/id_rsa to ssh agent
DEBUG: [common/sshtools.py:197 SSH.unlock_ssh_agent] Password available: True
DEBUG: [common/mount.py:298 SSH.mountprocess_lock_acquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/12005.lock
INFO: [common/mount.py:203 SSH.mount] Mountpoint /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint is already mounted
DEBUG: [common/mount.py:319 SSH.set_mount_lock] Set mount lock /home/user/.local/share/backintime/mnt/A5868FDC/locks/12005.lock
DEBUG: [common/mount.py:307 SSH.mountprocess_lock_release] Release mountprocess lock /home/user/.local/share/backintime/mnt/12005.lock
Do you really want to remove this snapshots?
(no/yes): yes
DEBUG: [common/sshtools.py:244 SSH.unlock_ssh_agent] Private key /home/user/.ssh/id_rsa is already unlocked in ssh agent
DEBUG: [common/mount.py:298 SSH.mountprocess_lock_acquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/12005.lock
INFO: [common/mount.py:232 SSH.umount] Mountpoint /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint still in use. Keep mounted
DEBUG: [common/mount.py:337 SSH.del_mount_lock] Remove mount lock /home/user/.local/share/backintime/mnt/A5868FDC/locks/12005.lock
DEBUG: [common/mount.py:307 SSH.mountprocess_lock_release] Release mountprocess lock /home/user/.local/share/backintime/mnt/12005.lock

The snapshots list ok, and everything else seems ok.

user@tigger:~$ backintime snapshots-list
INFO: Mountpoint /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint is already mounted
SnapshotID: 20151110-142002-940
SnapshotID: 20151110-091443-236
INFO: Mountpoint /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint still in use. Keep mounted
@Germar Germar added the bug label Nov 11, 2015
@Germar Germar added this to the 1.1.10 milestone Nov 11, 2015
@Germar
Copy link
Member

Germar commented Nov 11, 2015

This seems to be two different problems. Deleting in GUI works (the snapshot is gone) but it is still displayed in the snapshot list. Seems like the update of the list is to fast when using SSH mode. When you manually press 'Refresh Snapshot List' the snapshot should be gone in the list, too.

The command backintime remove seems to be broken completely. I'll have a look.

@colinl
Copy link
Author

colinl commented Nov 11, 2015

For me it is not working at all the GUI, on restarting BIT the snapshot is still there and the files are still on the destination.
Running backintime-qt4 --debug shows that it is a permissions problem. I see

PermissionError: [Errno 13] Permission denied: '/home/user/.local/share/backintime/mnt/1_10583/backintime/tigger/user/1/20151110-142002-940/backup/home/user/backups/sqldumps/sqldumps_no_date/uks51831_phpgedview.sql'

When I look at the permissions on that file through the mount point in the error I see

-rw-r--r-- 1 user test 1260796 Oct  1 10:59

but when I look at it directly on the server I see

-rw-r--r-- 1 user user 1260796 2015-10-01 10:59 

The original file is user:user

I guess that this may be to do with the fact that the user and group ids do not match between the client and server.

@Germar
Copy link
Member

Germar commented Nov 11, 2015

The BIT mounts the remote path with sshfs -o idmap=user. This makes sure that files you create local with your local user will be owned on remote by the remote user. The group shouldn't matter as the user already has read and write permissions.

Could you please check the remote filesystem for errors? E.g. fsck.ext4 /dev/sdXX

@colinl
Copy link
Author

colinl commented Nov 11, 2015

I am confident the disk is ok, and I get
$ sudo fsck /dev/sdb1
fsck from util-linux 2.26.2
e2fsck 1.42.12 (29-Aug-2014)
/dev/sdb1: clean, 49345/19537920 files, 61468441/78142464 blocks

Looking at the enclosing folder I see
dr-xr-xr-x 1 user test 4096 Nov 10 10:42 sqldumps_no_date
is that the problem? The permissions are the same when I look on the server or via the mount point.
I have full permissions on the original directory.

@Germar
Copy link
Member

Germar commented Nov 11, 2015

Yes, this will cause the troubles as you need write permissions for the folder to delete a file. If you run BIT without Full rsync mode it will remove all write permissions to prevent accidental overwriting of backup files (permissions are stored in a separate file). But the remove_snapshot method should make all folders writeable before trying to remove...

Can you please post the full output of backintime-qt4 --debug after trying to remove? I guess the find /path -type d -exec chmod u+wx + command fails before removing

@colinl
Copy link
Author

colinl commented Nov 11, 2015

I should have posted that in the first place. I don't see any reference to the find command in the output, has it missed it for some reason?

$ backintime-qt4 --debug
DEBUG: [common/backintime.py:450 arg_parse] Arguments: {'debug': True} | unknownArgs: []

Back In Time
Version: 1.1.8

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.

DEBUG: [common/backintime.py:496 getConfig] config file: /home/user/.config/backintime
DEBUG: [common/backintime.py:497 getConfig] profiles: ['1']
DEBUG: [common/pluginmanager.py:88 PluginManager.load_plugins] Register plugin path /usr/share/backintime/plugins
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin qt4plugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin userscriptsplugin.py
DEBUG: [common/pluginmanager.py:104 PluginManager.load_plugins] Add plugin notifyplugin.py
DEBUG: [common/snapshots.py:727 Snapshots.get_snapshots_list] Failed to get snapshots list: [Errno 2] No such file or directory: '/home/user/.local/share/backintime/mnt/1_10850/backintime'
DEBUG: [common/snapshots.py:917 Snapshots.has_old_snapshots] Found old snapshots: False
DEBUG: [common/sshtools.py:192 SSH.unlock_ssh_agent] Add private key /home/user/.ssh/id_rsa to ssh agent
DEBUG: [common/sshtools.py:197 SSH.unlock_ssh_agent] Password available: True
DEBUG: [common/mount.py:298 SSH.mountprocess_lock_acquire] Acquire mountprocess lock /home/user/.local/share/backintime/mnt/10850.lock
DEBUG: [common/sshtools.py:374 SSH.check_ping_host] Check ping host
DEBUG: [common/sshtools.py:383 SSH.check_ping_host] Host owl.local is available
DEBUG: [common/sshtools.py:248 SSH.check_fuse] Check fuse
DEBUG: [common/sshtools.py:270 SSH.check_login] Check login
DEBUG: [common/sshtools.py:338 SSH.check_remote_folder] Check remote folder
DEBUG: [common/sshtools.py:351 SSH.check_remote_folder] Call command: ssh -p 22 -o ServerAliveInterval=240 -o IdentityFile=/home/user/.ssh/id_rsa user@owl.local d=0;test -e /media/usbhdd/backups/ || d=1;test $d -eq 1 && mkdir /media/usbhdd/backups/; err=$?;test $d -eq 1 && exit $err;test -d /media/usbhdd/backups/ || exit 11;test -w /media/usbhdd/backups/ || exit 12;test -x /media/usbhdd/backups/ || exit 13;exit 20
DEBUG: [common/sshtools.py:356 SSH.check_remote_folder] Command returncode: 20
DEBUG: [common/sshtools.py:124 SSH._mount] Call mount command: sshfs -p 22 -o ServerAliveInterval=240 -o IdentityFile=/home/user/.ssh/id_rsa -o idmap=user user@owl.local:/media/usbhdd/backups/ /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint
INFO: [common/mount.py:211 SSH.mount] mount ssh: user@owl.local:/media/usbhdd/backups/ on /home/user/.local/share/backintime/mnt/A5868FDC/mountpoint
DEBUG: [common/mount.py:319 SSH.set_mount_lock] Set mount lock /home/user/.local/share/backintime/mnt/A5868FDC/locks/10850.lock
DEBUG: [common/mount.py:307 SSH.mountprocess_lock_release] Release mountprocess lock /home/user/.local/share/backintime/mnt/10850.lock
INFO: [common/tools.py:744 inhibitSuspend] Inhibit Suspend started. Reason: deleting files
Traceback (most recent call last):
  File "/usr/lib/python3.4/shutil.py", line 424, in _rmtree_safe_fd
    os.unlink(name, dir_fd=topfd)
PermissionError: [Errno 13] Permission denied: 'uks51831_phpgedview.sql'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/share/backintime/qt4/snapshotsdialog.py", line 379, in on_btn_delete_clicked
    self.snapshots.delete_path(snapshot_id, self.path)
  File "/usr/share/backintime/common/snapshots.py", line 1948, in delete_path
    shutil.rmtree(full_path, onerror = handle_error)
  File "/usr/lib/python3.4/shutil.py", line 468, in rmtree
    _rmtree_safe_fd(fd, path, onerror)
  File "/usr/lib/python3.4/shutil.py", line 406, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/usr/lib/python3.4/shutil.py", line 406, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/usr/lib/python3.4/shutil.py", line 406, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/usr/lib/python3.4/shutil.py", line 406, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/usr/lib/python3.4/shutil.py", line 406, in _rmtree_safe_fd
    _rmtree_safe_fd(dirfd, fullname, onerror)
  File "/usr/lib/python3.4/shutil.py", line 426, in _rmtree_safe_fd
    onerror(os.unlink, fullname, sys.exc_info())
  File "/usr/share/backintime/common/snapshots.py", line 1941, in handle_error
    fn(path)
PermissionError: [Errno 13] Permission denied: '/home/user/.local/share/backintime/mnt/1_10850/backintime/tigger/user/1/20151110-142002-940/backup/home/user/backups/sqldumps/sqldumps_no_date/uks51831_phpgedview.sql'
QInotifyFileSystemWatcherEngine::addPaths: inotify_add_watch failed: No such file or directory
QFileSystemWatcher: failed to add paths: /home/user/.local/share/backintime/mnt/1_10850/backintime/tigger/user/1/20151110-142002-940/backup/home/user/bin

@Germar
Copy link
Member

Germar commented Nov 11, 2015

Oh, okay. You're talking about deleting a folder inside a snapshot. I thought it's about removing a whole snapshot.

I was able to reproduce this and will have a look into it. Thanks for reporting

@colinl
Copy link
Author

colinl commented Nov 12, 2015

No, I am deleting a whole snapshot, though deleting it will involve deleting folders.
I will do some experiments to determine whether it is the deletion of a snapshot that involves deleting folders that is the trigger.

@colinl
Copy link
Author

colinl commented Nov 12, 2015

I took a new snapshot (call this s1), added a file and took another snapshot (s2) then added another file and took another snapshot (s3). I then tried deleting s2, but got effectively the same message as before (for the same file but for the snapshot I am trying to delete (output pasted below). I assume it is trying to unlink the tree from the snapshot, but it does not appear to have set the permissions first. If it would be useful I am probably competent to hack extra diagnostics into the source.

@colinl
Copy link
Author

colinl commented Nov 12, 2015

Having taught myself a little python I have instrumented snapshots.py#delete_path as in the attached file delete_path_py.txt and the result of trying to delete the snapshot is in delete_path_log.txt
If I interpret it correctly the call to os.access(dirname, os.W_OK) for the enclosing folder suggests that the folder is writable so it is not calling chmod on the folder, which I don't understand as I see
$ ls -l /home/user/.local/share/backintime/mnt/1_16957/backintime/tigger/user/1/20151112-084334-755/backup/home/user/backups/sqldumps/
total 4
dr-xr-xr-x 1 user test 4096 Nov 11 21:50 sqldumps_no_date

I am just off to work out how to display the folder permissions in python and will add that in.

delete_path_log.txt
delete_path_py.txt

@colinl
Copy link
Author

colinl commented Nov 12, 2015

Some results that look strange to me, with my limited knowledge.
I have added more debug to handle_error so it now starts

        def handle_error(fn, path, excinfo):
            logger.info("In handle_error %s" % path)
            dirname = os.path.dirname(path)
            logger.info("dirname %s" % dirname)
            logger.info(hex(os.stat(dirname).st_mode))
            if os.access(dirname, os.W_OK):
                logger.info("W_OK true")

and
hex(os.stat(dirname).st_mode)
is 0x416d but
if os.access(dirname, os.W_OK)
is showing true!

@colinl
Copy link
Author

colinl commented Nov 12, 2015

I have replaced, in snapshots.ph, the line
if not os.access(dirname, os.W_OK):
with
if not (os.stat(dirname).st_mode & stat.S_IWUSR):
and that seems to have fixed the fundamental problem. What the implication of that is I don't know.
However, having run right through removing everything it fails deleting the folder 'backup' (which is empty) in the top level snapshot directory, with a permission problem, calling fn(path) at the end of handle_error. The reason is that it has not set the write permission on the snapshot directory itself so it cannot remove the directory.
path is
/home/user/.local/share/backintime/mnt/1_20424/backintime/tigger/user/1/20151112-084334-755/backup/
and dirname is
/home/colinl/.local/share/backintime/mnt/1_20424/backintime/tigger/colinl/1/20151112-084334-755/backup
For some reason the path has a trailing / which I suspect may be causing the problem. I haven't worked out why yet

@colinl
Copy link
Author

colinl commented Nov 12, 2015

At the start of delete_path, stripping to trailing "/" from full path, so the line

full_path = self.get_snapshot_path_to(snapshot_id, path)

becomes

full_path = self.get_snapshot_path_to(snapshot_id, path).rstrip("/")

seems to fix the problem removing the directory "backup", and it appears that the snapshot is successfully removed. At the end it pops up a confusing dialog:
Exclude "/" from future snapshots?
but I don't know whether this is anything to do with the changes I have made.

@Germar
Copy link
Member

Germar commented Nov 12, 2015

No, I am deleting a whole snapshot, though deleting it will involve deleting folders.

and

However, having run right through removing everything it fails deleting the folder 'backup' (which is empty) in the top level snapshot directory

The delete button on Snapshot dialog is to delete a file or folder inside one or more snapshots. If you want to delete the whole snapshot use the Remove Snapshot button in main window top level menu bar

unbenannt

This will call Snapshots.remove_snapshot instead of Snapshot.delete_path


I have replaced, in snapshots.ph, the line
if not os.access(dirname, os.W_OK):
with
if not (os.stat(dirname).st_mode & stat.S_IWUSR):
and that seems to have fixed the fundamental problem. What the implication of that is I don't know.

I'm also not sure why os.access(dirname, os.W_OK) returns True. I remember that I used os.stat(dirname).st_mode & stat.S_IWUSR during writing that function and changed it to os.access later on.

Thanks for debuging. We already have three bugs in here 🙈 I'll split this up

@Germar Germar changed the title Unable to delete snapshot os.access(dirname, os.W_OK) does not recognize unwriteable folders in Snapshot.delete_path.handle_error Nov 12, 2015
@colinl
Copy link
Author

colinl commented Nov 12, 2015

Yes, you are right I see now, sorry for the confusion. I said at the start there may well be operator error involved. I was confused by the fact that if you click on a snapshot in the snapshots dialog it enables a button "delete", but I now see what it does. That also explains why after deleting '/' the folder for the snapshot is not deleted, though interestingly those empty snapshots do not appear in the main window any more. Recreating the 'backup' folder that it originally failed trying to remove makes them appear again.
I cannot at all understand why os.access does not work as expected. Google has not shown up any mention of such problems.

@colinl
Copy link
Author

colinl commented Nov 12, 2015

And if nothing else, I have learned some python :)

@Germar
Copy link
Member

Germar commented Nov 12, 2015

I just tried this local

$ ls -la
insgesamt 36
drwxr-xr-x   5 germar germar  4096 Nov 12 23:10 .
drwx------ 111 germar germar 20480 Nov 12 23:44 ..
dr-xr-xr-x   2 germar germar  4096 Nov 12 23:11 a
drwxr-xr-x   2 germar germar  4096 Nov 12 23:11 b
dr-xrwxr-x   2 germar germar  4096 Nov 12 23:11 c


$ python3
Python 3.4.3 (default, Oct 14 2015, 20:28:29) 
[GCC 4.8.4] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.access('a', os.W_OK)
False
>>> os.stat('a').st_mode & stat.S_IWUSR
0
>>> os.access('b', os.W_OK)
True
>>> os.stat('b').st_mode & stat.S_IWUSR
128
>>> os.access('c', os.W_OK)
False
>>> os.stat('c').st_mode & stat.S_IWUSR
0

and after mounting through sshfs

$ python3
Python 3.4.3 (default, Oct 14 2015, 20:28:29) 
[GCC 4.8.4] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.access('a', os.W_OK)
True
>>> os.stat('a').st_mode & stat.S_IWUSR
0
>>> os.access('b', os.W_OK)
True
>>> os.stat('b').st_mode & stat.S_IWUSR
128
>>> os.access('c', os.W_OK)
True
>>> os.stat('c').st_mode & stat.S_IWUSR
0

So os.access has problems with sshfs mounted shares


Just found this on os.access documentation:

Note: I/O operations may fail even when access() indicates that they would succeed, particularly for operations on network filesystems which may have permissions semantics beyond the usual POSIX permission-bit model.

Germar added a commit that referenced this issue Nov 12, 2015
@Germar
Copy link
Member

Germar commented Nov 12, 2015

I removed the whole if statement. It doesn't matter if we make the folder writeable if it's already writeable or not. This might take a nanosecond more time, but who cares...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants