Project

General

Profile

Actions
Copy link

Bug #43894

open

validating permissions for get requests takes much longer than list request

Added by Or Friedmann about 4 years ago. Updated about 4 years ago.

Status:
Triaged
Priority:
Normal
Assignee:
Or Friedmann
Target version:
Ceph - v15.0.0
% Done:

0%

Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
Ceph - v15.0.0
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket recalculating target
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket reading permissions
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket init op
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket verifying op mask
2020-01-30T11:09:18.501+0200 7fd259fc3700 20 req 3 0.003000083s s3:list_bucket required_mask= 1 user.op_mask=7
2020-01-30T11:09:18.501+0200 7fd259fc3700 2 req 3 0.003000083s s3:list_bucket verifying op permissions
2020-01-30T11:09:18.501+0200 7fd259fc3700 20 req 3 0.003000083s s3:list_bucket -- Getting permissions begin with perm_mask=49
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 req 3 0.003000083s s3:list_bucket Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) mask=49
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 Searching permissions for uid=testid
2020-01-30T11:09:18.501+0200 7fd259fc3700 5 Found permission: 15
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Searching permissions for group=1 mask=49
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Permissions for group not found
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Searching permissions for group=2 mask=49
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 Permissions for group not found
2020-01-30T11:09:18.502+0200 7fd259fc3700 5 req 3 0.004000110s s3:list_bucket - Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0), owner=testid, perm=1
2020-01-30T11:09:18.502+0200 7fd259fc3700 10 req 3 0.004000110s s3:list_bucket identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) requested perm (type)=1, policy perm=1, user_perm_mask=1, acl perm=1
2020-01-30T11:09:18.502+0200 7fd259fc3700 2 req 3 0.004000110s s3:list_bucket verifying op params

list ~ 4ms

2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj server signature=39d10b469fade649f43fc7c80720820fe8b3947ca8a720fca6eb9d09a9f071f4
2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj client signature=39d10b469fade649f43fc7c80720820fe8b3947ca8a720fca6eb9d09a9f071f4
2020-01-30T11:13:27.276+0200 7fd1e77ae700 15 req 6 0.003000082s s3:get_obj compare=0
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 req 6 0.003000082s s3:get_obj rgw::auth::s3::LocalEngine granted access
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 req 6 0.003000082s s3:get_obj rgw::auth::s3::AWSAuthStrategy granted access
2020-01-30T11:13:27.276+0200 7fd1e77ae700 2 req 6 0.003000082s s3:get_obj normalizing buckets and tenants
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 s->object=xxx s->bucket=hello
2020-01-30T11:13:27.276+0200 7fd1e77ae700 2 req 6 0.003000082s s3:get_obj init permissions
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 get_system_obj_state: rctx=0x7fd4c03eefb8 obj=default.rgw.meta:root:hello state=0x7fd320018c70 s->prefetch_data=0
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+root+hello : hit (requested=0x16, cached=0x17)
2020-01-30T11:13:27.276+0200 7fd1e77ae700 20 get_system_obj_state: s->obj_tag was set empty
2020-01-30T11:13:27.276+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+root+hello : hit (requested=0x11, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/&quot;&gt;&lt;Owner&gt;&lt;ID&gt;testid&lt;/ID&gt;&lt;DisplayName&gt;M. Tester</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance&quot; xsi:type="CanonicalUser"><ID>testid</ID><DisplayName>M. Tester</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 get_system_obj_state: rctx=0x7fd4c03ef478 obj=default.rgw.meta:users.uid:testid state=0x7fd320018c70 s->prefetch_data=0
2020-01-30T11:13:27.277+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+users.uid+testid : hit (requested=0x6, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 get_system_obj_state: s->obj_tag was set empty
2020-01-30T11:13:27.277+0200 7fd1e77ae700 20 Read xattr: user.rgw.idtag
2020-01-30T11:13:27.277+0200 7fd1e77ae700 10 cache get: name=default.rgw.meta+users.uid+testid : hit (requested=0x3, cached=0x17)
2020-01-30T11:13:27.277+0200 7fd1e77ae700 2 req 6 0.004000110s s3:get_obj recalculating target
2020-01-30T11:13:27.277+0200 7fd1e77ae700 2 req 6 0.004000110s s3:get_obj reading permissions
2020-01-30T11:13:27.278+0200 7fd1e77ae700 20 get_obj_state: rctx=0x7fd4c03f29e8 obj=hello:xxx state=0x7fd32001a018 s->prefetch_data=0
2020-01-30T11:13:27.278+0200 7fd1e77ae700 20 WARNING: blocking librados call
2020-01-30T11:13:27.283+0200 7fd1e77ae700 10 manifest: total_size = 571648542
2020-01-30T11:13:27.283+0200 7fd1e77ae700 20 get_obj_state: setting s->obj_tag to c3389a18-0740-434f-9232-c770e512d902.4155.5
2020-01-30T11:13:27.283+0200 7fd1e77ae700 15 decode_policy Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/&quot;&gt;&lt;Owner&gt;&lt;ID&gt;testid&lt;/ID&gt;&lt;DisplayName&gt;M. Tester</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance&quot; xsi:type="CanonicalUser"><ID>testid</ID><DisplayName>M. Tester</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy>
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj init op
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj verifying op mask
2020-01-30T11:13:27.283+0200 7fd1e77ae700 20 req 6 0.010000275s s3:get_obj required_mask= 1 user.op_mask=7
2020-01-30T11:13:27.283+0200 7fd1e77ae700 2 req 6 0.010000275s s3:get_obj verifying op permissions
2020-01-30T11:13:27.284+0200 7fd1e77ae700 20 req 6 0.011000302s s3:get_obj -- Getting permissions begin with perm_mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 req 6 0.011000302s s3:get_obj Searching permissions for identity=rgw::auth::SysReqApplier > rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for uid=testid
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Found permission: 15
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for group=1 mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Permissions for group not found
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Searching permissions for group=2 mask=49
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 Permissions for group not found
2020-01-30T11:13:27.284+0200 7fd1e77ae700 5 req 6 0.011000302s s3:get_obj - Getting permissions done for identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0), owner=testid, perm=1
2020-01-30T11:13:27.284+0200 7fd1e77ae700 10 req 6 0.011000302s s3:get_obj identity=rgw::auth::SysReqApplier -> rgw::auth::LocalApplier(acct_user=testid, acct_name=M. Tester, subuser=, perm_mask=15, is_admin=0) requested perm (type)=1, policy perm=1, user_perm_mask=15, acl perm=1
2020-01-30T11:13:27.284+0200 7fd1e77ae700 2 req 6 0.011000302s s3:get_obj verifying op params

Get ~ 11ms

Actions
Copy link

Also available in: Atom PDF