And more logs: 2012-09-11 21:03:38.357304 7faf0bf4f700 1 ====== req done req=0x141a650 http_status=403 ====== 2012-09-11 21:23:54.423185 7faf0bf4f700 20 dequeued request req=0x139a3d0 2012-09-11 21:23:54.423192 7faf0bf4f700 20 RGWWQ: empty 2012-09-11 21:23:54.423198 7faf0bf4f700 1 ====== starting new request req=0x139a3d0 ===== 2012-09-11 21:23:54.423237 7faf0bf4f700 2 req 58098:0.000039::::initializing 2012-09-11 21:23:54.423258 7faf0bf4f700 10 s->object=<NULL> s->bucket=<NULL> 2012-09-11 21:23:54.423265 7faf0bf4f700 20 FCGI_ROLE=RESPONDER 2012-09-11 21:23:54.423267 7faf0bf4f700 20 SCRIPT_FILENAME=/var/www/radosgw.fcgi 2012-09-11 21:23:54.423269 7faf0bf4f700 20 QUERY_STRING= 2012-09-11 21:23:54.423270 7faf0bf4f700 20 REQUEST_METHOD=GET 2012-09-11 21:23:54.423272 7faf0bf4f700 20 CONTENT_TYPE= 2012-09-11 21:23:54.423273 7faf0bf4f700 20 CONTENT_LENGTH= 2012-09-11 21:23:54.423274 7faf0bf4f700 20 HTTP_CONTENT_LENGTH= 2012-09-11 21:23:54.423276 7faf0bf4f700 20 SCRIPT_NAME=/ 2012-09-11 21:23:54.423277 7faf0bf4f700 20 REQUEST_URI=/ 2012-09-11 21:23:54.423279 7faf0bf4f700 20 DOCUMENT_URI=/ 2012-09-11 21:23:54.423280 7faf0bf4f700 20 DOCUMENT_ROOT=/var/www 2012-09-11 21:23:54.423282 7faf0bf4f700 20 SERVER_PROTOCOL=HTTP/1.0 2012-09-11 21:23:54.423283 7faf0bf4f700 20 GATEWAY_INTERFACE=CGI/1.1 2012-09-11 21:23:54.423284 7faf0bf4f700 20 SERVER_SOFTWARE=nginx/1.2.0 2012-09-11 21:23:54.423286 7faf0bf4f700 20 REMOTE_ADDR=10.177.95.19 2012-09-11 21:23:54.423287 7faf0bf4f700 20 REMOTE_PORT=60477 2012-09-11 21:23:54.423289 7faf0bf4f700 20 SERVER_ADDR=10.177.64.4 2012-09-11 21:23:54.423290 7faf0bf4f700 20 SERVER_PORT=80 ...skipping... 2012-09-11 22:23:44.530567 7faf0bf4f700 10 s->object=images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg s->bucket=ocdn 2012-09-11 22:23:44.530586 7faf0bf4f700 20 FCGI_ROLE=RESPONDER 2012-09-11 22:23:44.530588 7faf0bf4f700 20 SCRIPT_FILENAME=/var/www/radosgw.fcgi 2012-09-11 22:23:44.530589 7faf0bf4f700 20 QUERY_STRING= 2012-09-11 22:23:44.530591 7faf0bf4f700 20 REQUEST_METHOD=GET 2012-09-11 22:23:44.530592 7faf0bf4f700 20 CONTENT_TYPE= 2012-09-11 22:23:44.530593 7faf0bf4f700 20 CONTENT_LENGTH= 2012-09-11 22:23:44.530594 7faf0bf4f700 20 HTTP_CONTENT_LENGTH= 2012-09-11 22:23:44.530595 7faf0bf4f700 20 SCRIPT_NAME=/ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg 2012-09-11 22:23:44.530596 7faf0bf4f700 20 REQUEST_URI=/ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg 2012-09-11 22:23:44.530598 7faf0bf4f700 20 DOCUMENT_URI=/ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg 2012-09-11 22:23:44.530600 7faf0bf4f700 20 DOCUMENT_ROOT=/var/www 2012-09-11 22:23:44.530603 7faf0bf4f700 20 SERVER_PROTOCOL=HTTP/1.1 2012-09-11 22:23:44.530604 7faf0bf4f700 20 GATEWAY_INTERFACE=CGI/1.1 2012-09-11 22:23:44.530605 7faf0bf4f700 20 SERVER_SOFTWARE=nginx/1.2.0 2012-09-11 22:23:44.530606 7faf0bf4f700 20 REMOTE_ADDR=10.167.14.53 2012-09-11 22:23:44.530607 7faf0bf4f700 20 REMOTE_PORT=62145 2012-09-11 22:23:44.530608 7faf0bf4f700 20 SERVER_ADDR=10.177.64.4 2012-09-11 22:23:44.530609 7faf0bf4f700 20 SERVER_PORT=80 2012-09-11 22:23:44.530610 7faf0bf4f700 20 SERVER_NAME= 2012-09-11 22:23:44.530610 7faf0bf4f700 20 REDIRECT_STATUS=200 2012-09-11 22:23:44.530611 7faf0bf4f700 20 RGW_SHOULD_LOG=no 2012-09-11 22:23:44.530612 7faf0bf4f700 20 HTTP_HOST=10.177.64.4 2012-09-11 22:23:44.530613 7faf0bf4f700 20 HTTP_CONNECTION=keep-alive 2012-09-11 22:23:44.530614 7faf0bf4f700 20 HTTP_USER_AGENT=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_4) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.89 Safari/537.1 2012-09-11 22:23:44.530615 7faf0bf4f700 20 HTTP_ACCEPT=text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 2012-09-11 22:23:44.530616 7faf0bf4f700 20 HTTP_ACCEPT_ENCODING=gzip,deflate,sdch 2012-09-11 22:23:44.530617 7faf0bf4f700 20 HTTP_ACCEPT_LANGUAGE=en-US,en;q=0.8 2012-09-11 22:23:44.530618 7faf0bf4f700 20 HTTP_ACCEPT_CHARSET=ISO-8859-1,utf-8;q=0.7,*;q=0.3 2012-09-11 22:23:44.530620 7faf0bf4f700 2 req 68518:0.000117:s3:GET /ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg::getting op 2012-09-11 22:23:44.530626 7faf0bf4f700 2 req 68518:0.000123:s3:GET /ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg:get_obj:authorizing 2012-09-11 22:23:44.530630 7faf0bf4f700 2 req 68518:0.000127:s3:GET /ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg:get_obj:reading permissions 2012-09-11 22:23:44.530646 7faf0bf4f700 20 get_obj_state: rctx=0x7fb01c0122c0 obj=.rgw:ocdn state=0x7fb01c013248 s->prefetch_data=0 2012-09-11 22:23:44.531746 7faf0bf4f700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:23:44.531760 7faf0bf4f700 20 get_obj_state: rctx=0x7fb01c0122c0 obj=.rgw:ocdn state=0x7fb01c013248 s->prefetch_data=0 2012-09-11 22:23:44.531767 7faf0bf4f700 20 get_obj_state: rctx=0x7fb01c0122c0 obj=.rgw:ocdn state=0x7fb01c013248 s->prefetch_data=0 2012-09-11 22:23:44.531771 7faf0bf4f700 20 state for obj=.rgw:ocdn is not atomic, not appending atomic test 2012-09-11 22:23:44.531773 7faf0bf4f700 20 rados->read obj-ofs=0 read_ofs=0 read_len=16384 2012-09-11 22:23:44.532701 7faf0bf4f700 20 rados->read r=0 bl.length=65 2012-09-11 22:23:44.532721 7faf0bf4f700 20 rgw_get_bucket_info: bucket=ocdn(@.rgw.buckets[4168.2]) owner 0 2012-09-11 22:23:44.532734 7faf0bf4f700 20 get_obj_state: rctx=0x7fb01c0122c0 obj=ocdn: state=0x7fb01c013248 s->prefetch_data=0 2012-09-11 22:23:44.532750 7faf0bf4f700 15 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="Group"><URI>http://acs.amazonaws.com/groups/global/AllUsers</URI></Grantee><Permission>READ</Permission></Grant><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy> 2012-09-11 22:23:44.532770 7faf0bf4f700 20 get_obj_state: rctx=0x7fb01c0122c0 obj=ocdn:images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg state=0x7fb01c00a608 s->prefetch_data=1 2012-09-11 22:23:44.534298 7faf0bf4f700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:23:44.534315 7faf0bf4f700 15 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy> 2012-09-11 22:23:44.534327 7faf0bf4f700 2 req 68518:0.003823:s3:GET /ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg:get_obj:verifying op permissions 2012-09-11 22:23:44.534334 7faf0bf4f700 5 Searching permissions for uid=anonymous mask=1 2012-09-11 22:23:44.534336 7faf0bf4f700 5 Permissions for user not found 2012-09-11 22:23:44.534337 7faf0bf4f700 5 Searching permissions for group=1 mask=1 2012-09-11 22:23:44.534338 7faf0bf4f700 5 Permissions for group not found 2012-09-11 22:23:44.534339 7faf0bf4f700 5 Getting permissions id=anonymous owner=0 perm=0 2012-09-11 22:23:44.534341 7faf0bf4f700 10 uid=anonymous requested perm (type)=1, policy perm=0, user_perm_mask=15, acl perm=0 2012-09-11 22:23:44.534343 7faf0bf4f700 5 Searching permissions for uid=anonymous mask=16 2012-09-11 22:23:44.534344 7faf0bf4f700 5 Permissions for user not found 2012-09-11 22:23:44.534345 7faf0bf4f700 5 Searching permissions for group=1 mask=16 2012-09-11 22:23:44.534347 7faf0bf4f700 5 Found permission: 1 2012-09-11 22:23:44.534348 7faf0bf4f700 5 Getting permissions id=anonymous owner=0 perm=0 2012-09-11 22:23:44.534349 7faf0bf4f700 10 uid=anonymous requested perm (type)=16, policy perm=0, user_perm_mask=16, acl perm=0 2012-09-11 22:23:44.534357 7faf0bf4f700 10 --> Status: 403 2012-09-11 22:23:44.534367 7faf0bf4f700 10 --> Content-Length: 78 2012-09-11 22:23:44.534370 7faf0bf4f700 10 --> Accept-Ranges: bytes 2012-09-11 22:23:44.534373 7faf0bf4f700 10 --> Content-type: application/xml 2012-09-11 22:23:44.534480 7faf0bf4f700 2 req 68518:0.003976:s3:GET /ocdn/images/pulscms/NjQ7MDMsMWUwLDAsMCwx/0a9915212e85062de6134566905cf252.jpg:get_obj:http status=403 2012-09-11 22:23:44.534765 7faf0bf4f700 1 ====== req done req=0x13995c0 http_status=403 ====== Good put, and 403 after: 2012-09-11 22:37:34.677422 7fafddffb700 1 ====== starting new request req=0x139a3d0 ===== 2012-09-11 22:37:34.677466 7fafddffb700 2 req 71187:0.000044::::initializing 2012-09-11 22:37:34.677492 7fafddffb700 10 s->object=files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 s->bucket=ocdn 2012-09-11 22:37:34.677501 7fafddffb700 20 FCGI_ROLE=RESPONDER 2012-09-11 22:37:34.677502 7fafddffb700 20 SCRIPT_FILENAME=/var/www/radosgw.fcgi 2012-09-11 22:37:34.677503 7fafddffb700 20 QUERY_STRING= 2012-09-11 22:37:34.677504 7fafddffb700 20 REQUEST_METHOD=PUT 2012-09-11 22:37:34.677505 7fafddffb700 20 CONTENT_TYPE=text/plain 2012-09-11 22:37:34.677506 7fafddffb700 20 CONTENT_LENGTH=4721 2012-09-11 22:37:34.677507 7fafddffb700 20 HTTP_CONTENT_LENGTH=4721 2012-09-11 22:37:34.677508 7fafddffb700 20 SCRIPT_NAME=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.677509 7fafddffb700 20 REQUEST_URI=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.677510 7fafddffb700 20 DOCUMENT_URI=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.677511 7fafddffb700 20 DOCUMENT_ROOT=/var/www 2012-09-11 22:37:34.677512 7fafddffb700 20 SERVER_PROTOCOL=HTTP/1.1 2012-09-11 22:37:34.677512 7fafddffb700 20 GATEWAY_INTERFACE=CGI/1.1 2012-09-11 22:37:34.677513 7fafddffb700 20 SERVER_SOFTWARE=nginx/1.2.0 2012-09-11 22:37:34.677514 7fafddffb700 20 REMOTE_ADDR=10.174.53.77 2012-09-11 22:37:34.677515 7fafddffb700 20 REMOTE_PORT=48588 2012-09-11 22:37:34.677516 7fafddffb700 20 SERVER_ADDR=10.177.0.3 2012-09-11 22:37:34.677516 7fafddffb700 20 SERVER_PORT=80 2012-09-11 22:37:34.677517 7fafddffb700 20 SERVER_NAME= 2012-09-11 22:37:34.677518 7fafddffb700 20 REDIRECT_STATUS=200 2012-09-11 22:37:34.677519 7fafddffb700 20 RGW_SHOULD_LOG=no 2012-09-11 22:37:34.677520 7fafddffb700 20 HTTP_HOST=10.177.0.3 2012-09-11 22:37:34.677520 7fafddffb700 20 HTTP_ACCEPT_ENCODING=identity 2012-09-11 22:37:34.677521 7fafddffb700 20 HTTP_CONTENT_MD5=7Ous3d6VIkuW9GMzkSBJsQ== 2012-09-11 22:37:34.677522 7fafddffb700 20 HTTP_EXPECT=100-Continue 2012-09-11 22:37:34.677523 7fafddffb700 20 HTTP_DATE=Tue, 11 Sep 2012 20:37:46 GMT 2012-09-11 22:37:34.677524 7fafddffb700 20 HTTP_USER_AGENT=Boto/2.5.1 (linux2) 2012-09-11 22:37:34.677525 7fafddffb700 20 HTTP_CONTENT_TYPE=text/plain 2012-09-11 22:37:34.677526 7fafddffb700 20 HTTP_AUTHORIZATION=AWS 73VF66Q2JH5PT5K7QJ3A:5ucLfRdtJtAdcIcns2pgMowWAEE= 2012-09-11 22:37:34.677529 7fafddffb700 2 req 71187:0.000108:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1::getting op 2012-09-11 22:37:34.677534 7fafddffb700 2 req 71187:0.000113:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:authorizing 2012-09-11 22:37:34.677552 7fafddffb700 20 get_obj_state: rctx=0x7fb00c004960 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb00c004a18 s->prefetch_data=0 2012-09-11 22:37:34.679069 7fafddffb700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:37:34.679086 7fafddffb700 20 get_obj_state: rctx=0x7fb00c004960 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb00c004a18 s->prefetch_data=0 2012-09-11 22:37:34.680427 7fafddffb700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:37:34.680441 7fafddffb700 20 get_obj_state: rctx=0x7fb00c004960 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb00c004a18 s->prefetch_data=0 2012-09-11 22:37:34.680452 7fafddffb700 20 state for obj=.users:73VF66Q2JH5PT5K7QJ3A is not atomic, not appending atomic test 2012-09-11 22:37:34.680457 7fafddffb700 20 rados->read obj-ofs=0 read_ofs=0 read_len=16384 2012-09-11 22:37:34.681685 7fafddffb700 20 rados->read r=0 bl.length=231 2012-09-11 22:37:34.681748 7fafddffb700 10 get_canon_resource(): dest=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.681766 7fafddffb700 10 auth_hdr: 2012-09-11 22:37:34.681911 7fafddffb700 15 b64=5ucLfRdtJtAdcIcns2pgMowWAEE= 2012-09-11 22:37:34.681921 7fafddffb700 15 auth_sign=5ucLfRdtJtAdcIcns2pgMowWAEE= 2012-09-11 22:37:34.681922 7fafddffb700 15 compare=0 2012-09-11 22:37:34.681926 7fafddffb700 2 req 71187:0.004504:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:reading permissions 2012-09-11 22:37:34.681941 7fafddffb700 20 get_obj_state: rctx=0x7fb00c007050 obj=.rgw:ocdn state=0x7fb00c006578 s->prefetch_data=0 2012-09-11 22:37:34.683575 7fafddffb700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:37:34.683588 7fafddffb700 20 get_obj_state: rctx=0x7fb00c007050 obj=.rgw:ocdn state=0x7fb00c006578 s->prefetch_data=0 2012-09-11 22:37:34.683596 7fafddffb700 20 get_obj_state: rctx=0x7fb00c007050 obj=.rgw:ocdn state=0x7fb00c006578 s->prefetch_data=0 2012-09-11 22:37:34.683599 7fafddffb700 20 state for obj=.rgw:ocdn is not atomic, not appending atomic test 2012-09-11 22:37:34.683601 7fafddffb700 20 rados->read obj-ofs=0 read_ofs=0 read_len=16384 2012-09-11 22:37:34.684735 7fafddffb700 20 rados->read r=0 bl.length=65 2012-09-11 22:37:34.684755 7fafddffb700 20 rgw_get_bucket_info: bucket=ocdn(@.rgw.buckets[4168.2]) owner 0 2012-09-11 22:37:34.684769 7fafddffb700 20 get_obj_state: rctx=0x7fb00c007050 obj=ocdn: state=0x7fb00c006578 s->prefetch_data=0 2012-09-11 22:37:34.684786 7fafddffb700 15 Read AccessControlPolicy<AccessControlPolicy xmlns="http://s3.amazonaws.com/doc/2006-03-01/";><Owner><ID>0</ID><DisplayName>ocdn</DisplayName></Owner><AccessControlList><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="Group"><URI>http://acs.amazonaws.com/groups/global/AllUsers</URI></Grantee><Permission>READ</Permission></Grant><Grant><Grantee xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:type="CanonicalUser"><ID>0</ID><DisplayName>ocdn</DisplayName></Grantee><Permission>FULL_CONTROL</Permission></Grant></AccessControlList></AccessControlPolicy> 2012-09-11 22:37:34.684796 7fafddffb700 2 req 71187:0.007375:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:verifying op permissions 2012-09-11 22:37:34.684801 7fafddffb700 5 Searching permissions for uid=0 mask=2 2012-09-11 22:37:34.684803 7fafddffb700 5 Found permission: 15 2012-09-11 22:37:34.684804 7fafddffb700 10 uid=0 requested perm (type)=2, policy perm=2, user_perm_mask=2, acl perm=2 2012-09-11 22:37:34.684808 7fafddffb700 2 req 71187:0.007387:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:verifying op params 2012-09-11 22:37:34.684811 7fafddffb700 2 req 71187:0.007390:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:executing 2012-09-11 22:37:34.684831 7fafddffb700 15 supplied_md5_b64=7Ous3d6VIkuW9GMzkSBJsQ== 2012-09-11 22:37:34.684834 7fafddffb700 15 ceph_armor ret=16 2012-09-11 22:37:34.684841 7fafddffb700 15 supplied_md5=ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.684901 7fafddffb700 20 get_obj_state: rctx=0x7fb00c007050 obj=ocdn:files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 state=0x7fb00c00bda8 s->prefetch_data=0 2012-09-11 22:37:34.686278 7fafddffb700 20 prepare_atomic_for_write_impl: state is not atomic. state=0x7fb00c00bda8 2012-09-11 22:37:34.704899 7fafddffb700 10 --> ETag: "ecebacddde95224b96f46333 2012-09-11 22:37:34.704949 7fafddffb700 10 --> Content-Length: 0 2012-09-11 22:37:34.704954 7fafddffb700 10 --> Accept-Ranges: bytes 2012-09-11 22:37:34.704958 7fafddffb700 10 --> Status: 200 2012-09-11 22:37:34.704963 7fafddffb700 10 --> Content-type: application/xml 2012-09-11 22:37:34.705099 7fafddffb700 2 req 71187:0.027678:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:http status=200 2012-09-11 22:37:34.705454 7fafddffb700 1 ====== req done req=0x139a3d0 http_status=200 ====== 2012-09-11 22:37:34.708316 7faec76c6700 20 dequeued request req=0x1368860 2012-09-11 22:37:34.708326 7faec76c6700 20 RGWWQ: empty 2012-09-11 22:37:34.708333 7faec76c6700 1 ====== starting new request req=0x1368860 ===== 2012-09-11 22:37:34.708375 7faec76c6700 2 req 71188:0.000042::::initializing 2012-09-11 22:37:34.708402 7faec76c6700 10 s->object=files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 s->bucket=ocdn 2012-09-11 22:37:34.708408 7faec76c6700 10 meta>> HTTP_X_AMZ_ACL=public-read 2012-09-11 22:37:34.708425 7faec76c6700 10 x>> x-amz-acl:public-read 2012-09-11 22:37:34.708431 7faec76c6700 20 FCGI_ROLE=RESPONDER 2012-09-11 22:37:34.708432 7faec76c6700 20 SCRIPT_FILENAME=/var/www/radosgw.fcgi 2012-09-11 22:37:34.708434 7faec76c6700 20 QUERY_STRING=acl 2012-09-11 22:37:34.708435 7faec76c6700 20 REQUEST_METHOD=PUT 2012-09-11 22:37:34.708437 7faec76c6700 20 CONTENT_TYPE= 2012-09-11 22:37:34.708438 7faec76c6700 20 CONTENT_LENGTH=0 2012-09-11 22:37:34.708439 7faec76c6700 20 HTTP_CONTENT_LENGTH=0 2012-09-11 22:37:34.708440 7faec76c6700 20 SCRIPT_NAME=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.708441 7faec76c6700 20 REQUEST_URI=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.708441 7faec76c6700 20 DOCUMENT_URI=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.708442 7faec76c6700 20 DOCUMENT_ROOT=/var/www 2012-09-11 22:37:34.708443 7faec76c6700 20 SERVER_PROTOCOL=HTTP/1.1 2012-09-11 22:37:34.708444 7faec76c6700 20 GATEWAY_INTERFACE=CGI/1.1 2012-09-11 22:37:34.708446 7faec76c6700 20 SERVER_SOFTWARE=nginx/1.2.0 2012-09-11 22:37:34.708447 7faec76c6700 20 REMOTE_ADDR=10.174.53.77 2012-09-11 22:37:34.708447 7faec76c6700 20 REMOTE_PORT=48588 2012-09-11 22:37:34.708448 7faec76c6700 20 SERVER_ADDR=10.177.0.3 2012-09-11 22:37:34.708450 7faec76c6700 20 SERVER_PORT=80 2012-09-11 22:37:34.708451 7faec76c6700 20 SERVER_NAME= 2012-09-11 22:37:34.708452 7faec76c6700 20 REDIRECT_STATUS=200 2012-09-11 22:37:34.708453 7faec76c6700 20 RGW_SHOULD_LOG=no 2012-09-11 22:37:34.708454 7faec76c6700 20 HTTP_HOST=10.177.0.3 2012-09-11 22:37:34.708455 7faec76c6700 20 HTTP_ACCEPT_ENCODING=identity 2012-09-11 22:37:34.708456 7faec76c6700 20 HTTP_DATE=Tue, 11 Sep 2012 20:37:46 GMT 2012-09-11 22:37:34.708457 7faec76c6700 20 HTTP_X_AMZ_ACL=public-read 2012-09-11 22:37:34.708458 7faec76c6700 20 HTTP_AUTHORIZATION=AWS 73VF66Q2JH5PT5K7QJ3A:xHPA2K5QvuehAvKH9WdOvf+ZKzE= 2012-09-11 22:37:34.708458 7faec76c6700 20 HTTP_USER_AGENT=Boto/2.5.1 (linux2) 2012-09-11 22:37:34.708462 7faec76c6700 2 req 71188:0.000129:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1::getting op 2012-09-11 22:37:34.708467 7faec76c6700 2 req 71188:0.000134:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:authorizing 2012-09-11 22:37:34.708486 7faec76c6700 20 get_obj_state: rctx=0x7fb2a4007e60 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb2a4007f18 s->prefetch_data=0 2012-09-11 22:37:34.709812 7faec76c6700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:37:34.709828 7faec76c6700 20 get_obj_state: rctx=0x7fb2a4007e60 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb2a4007f18 s->prefetch_data=0 2012-09-11 22:37:34.711091 7faec76c6700 20 get_obj_state: s->obj_tag was set empty 2012-09-11 22:37:34.711101 7faec76c6700 20 get_obj_state: rctx=0x7fb2a4007e60 obj=.users:73VF66Q2JH5PT5K7QJ3A state=0x7fb2a4007f18 s->prefetch_data=0 2012-09-11 22:37:34.711108 7faec76c6700 20 state for obj=.users:73VF66Q2JH5PT5K7QJ3A is not atomic, not appending atomic test 2012-09-11 22:37:34.711111 7faec76c6700 20 rados->read obj-ofs=0 read_ofs=0 read_len=16384 2012-09-11 22:37:34.712485 7faec76c6700 20 rados->read r=0 bl.length=231 2012-09-11 22:37:34.712655 7faec76c6700 10 get_canon_resource(): dest=/ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1 2012-09-11 22:37:34.712659 7faec76c6700 10 auth_hdr: 2012-09-11 22:37:34.712735 7faec76c6700 15 b64=7pIUzzJaX/EyTV89LMXwcqvS06w= 2012-09-11 22:37:34.712742 7faec76c6700 15 auth_sign=xHPA2K5QvuehAvKH9WdOvf+ZKzE= 2012-09-11 22:37:34.712744 7faec76c6700 15 compare=65 2012-09-11 22:37:34.712747 7faec76c6700 10 failed to authorize request 2012-09-11 22:37:34.712754 7faec76c6700 10 --> Status: 403 2012-09-11 22:37:34.712766 7faec76c6700 10 --> Content-Length: 78 2012-09-11 22:37:34.712769 7faec76c6700 10 --> Accept-Ranges: bytes 2012-09-11 22:37:34.712772 7faec76c6700 10 --> Content-type: application/xml 2012-09-11 22:37:34.712887 7faec76c6700 2 req 71188:0.004554:s3:PUT /ocdn/files/pulscms/MjU7MDA_/ecebacddde95224b96f46333912049b1:put_obj:http status=403 2012-09-11 22:37:34.713093 7faec76c6700 1 ====== req done req=0x1368860 http_status=403 ====== On Tue, Sep 11, 2012 at 7:46 PM, Sławomir Skowron <szibis@xxxxxxxxx> wrote: > On Tue, Sep 11, 2012 at 6:48 PM, Yehuda Sadeh <yehuda@xxxxxxxxxxx> wrote: >> On Tue, Sep 11, 2012 at 9:45 AM, Yehuda Sadeh <yehuda@xxxxxxxxxxx> wrote: >>> On Tue, Sep 11, 2012 at 7:28 AM, Sławomir Skowron <szibis@xxxxxxxxx> wrote: >>>> Every acl operation ending with 403 in PUT. >>>> >>>> ~# s3 -u test oc >>>> Bucket Status >>>> -------------------------------------------------------- -------------------- >>>> oc Access Denied >>>> >>>> Anyone know why, and how to enable this bucket ?? Now i have problems >>>> with cluster, because there is no way to upload new file >>>> >>>> ~# s3 -u getacl oc >>>> >>>> ERROR: ErrorAccessDenied >>>> >>> >>> User somehow lost bucket ownership (was it actually the owner?). Do >>> you know how to reproduce the issue? any remaining logs? >>> >>> Try getting bucket info: >>> >>> # radosgw-admin bucket stats --bucket=oc >>> >>> If that doesn't fail and actually shows relevant info, try checking >>> whether the user credentials match the s3 tool credentials. >>> >> Oh, and thinking about it some more.. 'oc' is a too short name for a >> bucket (requires min of 3 chars). How did you create it? The failure >> may be related. > > Yes i made a shortcut of name :)) > > Right now every bucket in pool, are afected > > :~#radosgw-admin bucket stats --bucket=lvstest > { "bucket": "lvstest", > "pool": ".rgw.buckets", > "id": "1142048.1", > "marker": "1142048.1", > "owner": "0", > "usage": { "rgw.main": { "size_kb": 1, > "size_kb_actual": 4, > "num_objects": 1}}} > :~# radosgw-admin bucket stats --bucket=ocdn > { "bucket": "ocdn", > "pool": ".rgw.buckets", > "id": "4168.2", > "marker": "4168.2", > "owner": "0", > "usage": { "rgw.main": { "size_kb": 513059717, > "size_kb_actual": 516402364, > "num_objects": 1606730}}} > > Credentials from radosgw-admin user info match that from clients requests. > > Every GET, PUT, HEAD using this credentials works fine, but only one > operations does not work (403 from radosgw) - setting acl for object > for a public-read. Setting canned acl with PUT for public-read from > s3lib work good, but get/set acl failed. > > list bucket object works good, and list buckets via s3 client. > > Now i can't reproduce, but i will dig logs from radosgw, for related > time, when this happend. > > Example 403 from radosgw log, before that PUT of object ends with 200: > > 2012-09-11 19:36:34.346312 7fb25d7fa700 1 ====== req done > req=0x1435980 http_status=403 ====== > 2012-09-11 19:37:04.342894 7fb25d7fa700 20 dequeued request req=0x13994c0 > 2012-09-11 19:37:04.342903 7fb25d7fa700 20 RGWWQ: empty > 2012-09-11 19:37:04.342910 7fb25d7fa700 1 ====== starting new request > req=0x13994c0 ===== > 2012-09-11 19:37:04.342948 7fb25d7fa700 2 req 39665:0.000038::::initializing > 2012-09-11 19:37:04.342971 7fb25d7fa700 10 > s->object=images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg > s->bucket=ocdn > 2012-09-11 19:37:04.342983 7fb25d7fa700 10 meta>> HTTP_X_AMZ_ACL=public-read > 2012-09-11 19:37:04.342991 7fb25d7fa700 10 x>> x-amz-acl:public-read > 2012-09-11 19:37:04.342996 7fb25d7fa700 20 FCGI_ROLE=RESPONDER > 2012-09-11 19:37:04.342997 7fb25d7fa700 20 SCRIPT_FILENAME=/var/www/radosgw.fcgi > 2012-09-11 19:37:04.342999 7fb25d7fa700 20 QUERY_STRING=acl > 2012-09-11 19:37:04.343001 7fb25d7fa700 20 REQUEST_METHOD=PUT > 2012-09-11 19:37:04.343002 7fb25d7fa700 20 CONTENT_TYPE= > 2012-09-11 19:37:04.343003 7fb25d7fa700 20 CONTENT_LENGTH=0 > 2012-09-11 19:37:04.343004 7fb25d7fa700 20 HTTP_CONTENT_LENGTH=0 > 2012-09-11 19:37:04.343005 7fb25d7fa700 20 > SCRIPT_NAME=/ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg > 2012-09-11 19:37:04.343006 7fb25d7fa700 20 > REQUEST_URI=/ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg > 2012-09-11 19:37:04.343007 7fb25d7fa700 20 > DOCUMENT_URI=/ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg > 2012-09-11 19:37:04.343008 7fb25d7fa700 20 DOCUMENT_ROOT=/var/www > 2012-09-11 19:37:04.343009 7fb25d7fa700 20 SERVER_PROTOCOL=HTTP/1.1 > 2012-09-11 19:37:04.343010 7fb25d7fa700 20 GATEWAY_INTERFACE=CGI/1.1 > 2012-09-11 19:37:04.343011 7fb25d7fa700 20 SERVER_SOFTWARE=nginx/1.2.0 > 2012-09-11 19:37:04.343012 7fb25d7fa700 20 REMOTE_ADDR=10.177.62.9 > 2012-09-11 19:37:04.343013 7fb25d7fa700 20 REMOTE_PORT=56378 > 2012-09-11 19:37:04.343014 7fb25d7fa700 20 SERVER_ADDR=10.177.0.3 > 2012-09-11 19:37:04.343015 7fb25d7fa700 20 SERVER_PORT=80 > 2012-09-11 19:37:04.343016 7fb25d7fa700 20 SERVER_NAME= > 2012-09-11 19:37:04.343017 7fb25d7fa700 20 REDIRECT_STATUS=200 > 2012-09-11 19:37:04.343018 7fb25d7fa700 20 RGW_SHOULD_LOG=no > 2012-09-11 19:37:04.343019 7fb25d7fa700 20 HTTP_HOST=10.177.0.3 > 2012-09-11 19:37:04.343020 7fb25d7fa700 20 HTTP_ACCEPT_ENCODING=identity > 2012-09-11 19:37:04.343021 7fb25d7fa700 20 HTTP_DATE=Tue, 11 Sep 2012 > 17:37:02 GMT > 2012-09-11 19:37:04.343022 7fb25d7fa700 20 HTTP_X_AMZ_ACL=public-read > 2012-09-11 19:37:04.343023 7fb25d7fa700 20 HTTP_AUTHORIZATION=AWS > 73VF66Q2JH5PT5K7QJ3A:mh7yBIFGPtdI1MAjW39/1ywV580= > 2012-09-11 19:37:04.343024 7fb25d7fa700 20 HTTP_USER_AGENT=Boto/2.5.2 (linux2) > 2012-09-11 19:37:04.343026 7fb25d7fa700 2 req 39665:0.000116:s3:PUT > /ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg::getting > op > 2012-09-11 19:37:04.343031 7fb25d7fa700 2 req 39665:0.000121:s3:PUT > /ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg:put_obj:authorizing > 2012-09-11 19:37:04.343047 7fb25d7fa700 20 get_obj_state: > rctx=0x7fb23c006340 obj=.users:73VF66Q2JH5PT5K7QJ3A > state=0x7fb23c00b468 s->prefetch_data=0 > 2012-09-11 19:37:04.344527 7fb25d7fa700 20 get_obj_state: s->obj_tag > was set empty > 2012-09-11 19:37:04.344542 7fb25d7fa700 20 get_obj_state: > rctx=0x7fb23c006340 obj=.users:73VF66Q2JH5PT5K7QJ3A > state=0x7fb23c00b468 s->prefetch_data=0 > 2012-09-11 19:37:04.345847 7fb25d7fa700 20 get_obj_state: s->obj_tag > was set empty > 2012-09-11 19:37:04.345858 7fb25d7fa700 20 get_obj_state: > rctx=0x7fb23c006340 obj=.users:73VF66Q2JH5PT5K7QJ3A > state=0x7fb23c00b468 s->prefetch_data=0 > 2012-09-11 19:37:04.345863 7fb25d7fa700 20 state for > obj=.users:73VF66Q2JH5PT5K7QJ3A is not atomic, not appending atomic > test > 2012-09-11 19:37:04.345866 7fb25d7fa700 20 rados->read obj-ofs=0 > read_ofs=0 read_len=16384 > 2012-09-11 19:37:04.347069 7fb25d7fa700 20 rados->read r=0 bl.length=231 > 2012-09-11 19:37:04.347121 7fb25d7fa700 10 get_canon_resource(): > dest=/ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg > 2012-09-11 19:37:04.347126 7fb25d7fa700 10 auth_hdr: > 2012-09-11 19:37:04.347195 7fb25d7fa700 15 b64=9qJQCGmPbTXcT6a4qD3kED0PPdY= > 2012-09-11 19:37:04.347198 7fb25d7fa700 15 > auth_sign=mh7yBIFGPtdI1MAjW39/1ywV580= > 2012-09-11 19:37:04.347199 7fb25d7fa700 15 compare=52 > 2012-09-11 19:37:04.347201 7fb25d7fa700 10 failed to authorize request > 2012-09-11 19:37:04.347208 7fb25d7fa700 10 --> Status: 403 > 2012-09-11 19:37:04.347218 7fb25d7fa700 10 --> Content-Length: 78 > 2012-09-11 19:37:04.347220 7fb25d7fa700 10 --> Accept-Ranges: bytes > 2012-09-11 19:37:04.347223 7fb25d7fa700 10 --> Content-type: application/xml > 2012-09-11 19:37:04.347346 7fb25d7fa700 2 req 39665:0.004436:s3:PUT > /ocdn/images/pulscms/ZjM7MDA_/d6d6df3de5afa365d0fb7379fdbd75b8.jpg:put_obj:http > status=403 > 2012-09-11 19:37:04.347600 7fb25d7fa700 1 ====== req done > req=0x13994c0 http_status=403 ====== > 2012-09-11 19:40:04.354709 7fb25d7fa700 20 dequeued request req=0x13994c0 > > Interesting is that second cluster, which is replicated via s3 client, > get the same issue, from that in production one. Is this can be > generated by many error on radosgw layer ?? > > I will try to find beginning of this problems in logs. > >> >> Yehuda > > > > -- > ----- > Pozdrawiam > > Sławek "sZiBis" Skowron -- ----- Pozdrawiam Sławek "sZiBis" Skowron -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
