Ceph » Linux kernel client

It looks like the kernel client tries to access the filesystem root on mount, even when it is mounting a sub path. This will fail if the client has caps that restrict it by path. I seem to recall that the fuse client had this problem too until it was fixed at the same time we were adding the path restrictions.

Seen while running TestVolumeClient against kernel client (http://tracker.ceph.com/issues/9466)
http://qa-proxy.ceph.com/teuthology/jspray-2016-08-30_12:07:21-kcephfs:recovery-master-testing-basic-mira/392449/teuthology.log

Caps look like:

2016-08-30T12:26:10.718 INFO:teuthology.orchestra.run.mira030.stdout:        {
2016-08-30T12:26:10.718 INFO:teuthology.orchestra.run.mira030.stdout:            "entity": "client.guest",
2016-08-30T12:26:10.718 INFO:teuthology.orchestra.run.mira030.stdout:            "key": "AQBde8VXrnkICBAAMDsCITn4iLFyLKxv35tlow==",
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:            "caps": {
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:                "mds": "allow rw path=\/volumes\/grpid\/volid_0",
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:                "mon": "allow r",
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:                "osd": "allow rw pool=cephfs_data namespace=fsvolumens_volid_0" 
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:            }
2016-08-30T12:26:10.719 INFO:teuthology.orchestra.run.mira030.stdout:        },

Mount commands looks like:

2016-08-30T12:26:11.978 INFO:teuthology.orchestra.run.mira030:Running: 'sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage /sbin/mount.ceph 172.21.4.116:6789:/volumes/grpid/volid_0 /home/ubuntu/cephtest/mnt.guest.0 -v -o name=guest,secretfile=/home/ubuntu/cephtest/ceph.data/client.guest.secret'
2016-08-30T12:26:12.140 INFO:teuthology.orchestra.run.mira030.stdout:parsing options: name=guest,secretfile=/home/ubuntu/cephtest/ceph.data/client.guest.secret
2016-08-30T12:26:12.141 INFO:teuthology.orchestra.run.mira030.stdout:mount error 13 = Permission denied

Client sends this request to server:

2016-08-30 12:26:12.133845 7fc64c622700  1 -- 172.21.4.116:6805/15963 <== client.14170 172.21.4.116:0/4186839042 2 ==== client_request(client.14170:1 getattr p #1 2016-08-30 12:26:12.125814) v2 ==== 122+0+0 (2888356563 0 0) 0x559a5d8a3600 con 0x559a5d7e0f00
2016-08-30 12:26:12.133893 7fc64c622700  4 mds.0.server handle_client_request client_request(client.14170:1 getattr p #1 2016-08-30 12:26:12.125814) v2
2016-08-30 12:26:12.133902 7fc64c622700 20 mds.0.server get_session have 0x559a5d79a000 client.14170 172.21.4.116:0/4186839042 state open
2016-08-30 12:26:12.133908 7fc64c622700 15 mds.0.server  oldest_client_tid=1
2016-08-30 12:26:12.133917 7fc64c622700  7 mds.0.cache request_start request(client.14170:1 cr=0x559a5d8a3600)
2016-08-30 12:26:12.133921 7fc64c622700  7 mds.0.server dispatch_client_request client_request(client.14170:1 getattr p #1 2016-08-30 12:26:12.125814) v2
2016-08-30 12:26:12.133927 7fc64c622700 10 mds.0.server rdlock_path_pin_ref request(client.14170:1 cr=0x559a5d8a3600) #1
2016-08-30 12:26:12.133931 7fc64c622700  7 mds.0.cache traverse: opening base ino 1 snap head
2016-08-30 12:26:12.133934 7fc64c622700 10 mds.0.cache path_traverse finish on snapid head
2016-08-30 12:26:12.133936 7fc64c622700 10 mds.0.server ref is [inode 1 [...2,head] / auth v6 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=0 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x559a5d6be000]
2016-08-30 12:26:12.133968 7fc64c622700 10 mds.0.locker acquire_locks request(client.14170:1 cr=0x559a5d8a3600)
2016-08-30 12:26:12.133972 7fc64c622700 20 mds.0.locker  must rdlock (isnap sync) [inode 1 [...2,head] / auth v6 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x559a5d6be000]
2016-08-30 12:26:12.133986 7fc64c622700 10 mds.0.locker  must authpin [inode 1 [...2,head] / auth v6 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x559a5d6be000]
2016-08-30 12:26:12.133999 7fc64c622700 10 mds.0.locker  auth_pinning [inode 1 [...2,head] / auth v6 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x559a5d6be000]
2016-08-30 12:26:12.134011 7fc64c622700 10 mds.0.cache.ino(1) auth_pin by 0x559a5d7a4d00 on [inode 1 [...2,head] / auth v6 ap=1+0 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x559a5d6be000] now 1+0
2016-08-30 12:26:12.134027 7fc64c622700  7 mds.0.locker rdlock_start  on (isnap sync) on [inode 1 [...2,head] / auth v6 ap=1+0 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=0 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x559a5d6be000]
2016-08-30 12:26:12.134038 7fc64c622700 10 mds.0.locker  got rdlock on (isnap sync r=1) [inode 1 [...2,head] / auth v6 ap=1+0 snaprealm=0x559a5d5bed80 dirtyparent f(v0 m2016-08-30 12:26:03.538717 1=0+1) n(v2 rc2016-08-30 12:26:05.099059 b237 6=2+4)/n(v0 1=0+1) (isnap sync r=1) (inest lock dirty) (iversion lock) caps={14161=pLsXs/-@4} | dirtyscattered=1 request=1 lock=1 dirfrag=1 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x559a5d6be000]
2016-08-30 12:26:12.134056 7fc64c622700 20 Session check_access path 
2016-08-30 12:26:12.134058 7fc64c622700 10 MDSAuthCap is_capable inode(path / owner 0:0 mode 041777) by caller 0:0 mask 1 new 0:0 cap: MDSAuthCaps[allow rw path="/volumes/grpid/volid_0"]
2016-08-30 12:26:12.134062 7fc64c622700 10 mds.0.server reply_client_request -13 ((13) Permission denied) client_request(client.14170:1 getattr p #1 2016-08-30 12:26:12.125814) v2
2016-08-30 12:26:12.134073 7fc64c622700 10 mds.0.server apply_allocated_inos 0 / [] / 0
2016-08-30 12:26:12.134076 7fc64c622700 20 mds.0.server lat 0.000405
2016-08-30 12:26:12.134078 7fc64c622700  1 -- 172.21.4.116:6805/15963 --> 172.21.4.116:0/4186839042 -- client_reply(???:1 = -13 (13) Permission denied) v1 -- ?+0 0x559a5d9aadc0 con 0x559a5d7e0f00