Actions
Bug #62809
closedNotify reason for EPERM failures due to application not enabled on RGW pool in the RGW log
% Done:
0%
Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
RGW is returning 403 error while creating buckets but not giving much details into why it is failing to create bucket. We had to debug the issue through RGW debug logs which was time consuming and not at all user friendly. Reference : https://bugzilla.redhat.com/show_bug.cgi?id=2028999. To notify end user on possible problem to write to pool, we are reporting a HEALTH_WARN if pool is empty (refer https://tracker.ceph.com/issues/57097).
It will be very helpful to add the possible cause for the failure to write to RGW pools in the rgw log. It will save time to debug this issue through rgw and osd debug logs.
Also good to add a teuthology testcase to test this scenario.
Updated by Matt Benjamin 8 months ago
In what sense was RGW "silently failing to create buckets?" Are you saying RGW returned 2XX/success after failing to create buckets?
Matt
Updated by Prashant D 8 months ago
Hi Matt,
Matt Benjamin wrote:
In what sense was RGW "silently failing to create buckets?" Are you saying RGW returned 2XX/success after failing to create buckets?
My bad, corrected the tracker description. RGW was not silently failing rather was giving 403 when osd_op failing with EPERM error. Would be possible to log descriptive error message based on EPERM error from osd and tag set in osd caps ?
Updated by Casey Bodley 8 months ago
- Subject changed from Notify reason for bucket creation failure due to application not enabled on RGW pool in the RGW log to Notify reason for EPERM failures due to application not enabled on RGW pool in the RGW log
Prashant D wrote:
My bad, corrected the tracker description. RGW was not silently failing rather was giving 403 when osd_op failing with EPERM error. Would be possible to log descriptive error message based on EPERM error from osd and tag set in osd caps ?
thanks Prashant. rgw issues rados reads and writes from many call sites, but most will go through the rgw_rados_operate() helpers:
https://github.com/ceph/ceph/blob/0ecc5f12/src/rgw/driver/rados/rgw_tools.cc#L179-L224
you could check for EPERM there to add the necessary log messages
Updated by Prashant D 3 months ago
This issue is not reproducible with latest main branch (commit-id: 49c27499af4ee9a90f69fcc6bf3597999d6efc7b)
user1@r444-22:~/ceph6/build$ MON=1 MGR=1 OSD=3 MDS=1 RGW=2 ../src/vstart.sh -n -d
user1@r444-22:~/ceph6/build$ ./bin/ceph -s
*** DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
2024-01-23T14:00:02.886-0500 7f529f95c700 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:00:02.898-0500 7f529f95c700 -1 WARNING: all dangerous and experimental features are enabled.
cluster:
id: 9b0a8b6f-51eb-432d-96fa-dc26b0de6c89
health: HEALTH_OK
services:
mon: 1 daemons, quorum a (age 63s)
mgr: x(active, since 55s)
mds: 1/1 daemons up
osd: 3 osds: 3 up (since 29s), 3 in (since 43s)
rgw: 2 daemons active (1 hosts, 1 zones)
data:
volumes: 1/1 healthy
pools: 7 pools, 7 pgs
objects: 233 objects, 586 KiB
usage: 3.0 GiB used, 300 GiB / 303 GiB avail
pgs: 7 active+clean
io:
client: 117 KiB/s rd, 5.1 KiB/s wr, 143 op/s rd, 82 op/s wr
user1@r444-22:~/ceph6/build$ for pool in .rgw.root default.rgw.log default.rgw.control default.rgw.meta default.rgw.buckets.index; do echo $pool;./bin/ceph osd pool application disable $pool rgw --yes-i-really-mean-it;done;
user1@r444-22:~/ceph6/build$ ./bin/ceph auth caps client.rgw.8000 osd 'allow rwx tag rgw *=*';
user1@r444-22:~/ceph6/build$./bin/ceph auth caps client.rgw.8001 osd 'allow rwx tag rgw *=*'
user1@r444-22:~/ceph6/build$ ./bin/ceph health detail
*** DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
2024-01-23T14:00:32.198-0500 7f2373282700 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:00:32.218-0500 7f2373282700 -1 WARNING: all dangerous and experimental features are enabled.
HEALTH_WARN 4 pool(s) do not have an application enabled
[WRN] POOL_APP_NOT_ENABLED: 4 pool(s) do not have an application enabled
application not enabled on pool '.rgw.root'
application not enabled on pool 'default.rgw.log'
application not enabled on pool 'default.rgw.control'
application not enabled on pool 'default.rgw.meta'
use 'ceph osd pool application enable <pool-name> <app-name>', where <app-name> is 'cephfs', 'rbd', 'rgw', or freeform for custom applications.
user1@r444-22:~/ceph6/build$ ./bin/ceph df
*** DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
2024-01-23T14:00:36.034-0500 7fec5f68b700 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:00:36.050-0500 7fec5f68b700 -1 WARNING: all dangerous and experimental features are enabled.
--- RAW STORAGE ---
CLASS SIZE AVAIL USED RAW USED %RAW USED
ssd 303 GiB 300 GiB 3.0 GiB 3.0 GiB 0.99
TOTAL 303 GiB 300 GiB 3.0 GiB 3.0 GiB 0.99
--- POOLS ---
POOL ID PGS STORED OBJECTS USED %USED MAX AVAIL
.mgr 1 1 577 KiB 2 1.7 MiB 0 99 GiB
cephfs.a.meta 2 16 2.4 KiB 22 96 KiB 0 99 GiB
cephfs.a.data 3 128 0 B 0 0 B 0 99 GiB
.rgw.root 4 32 1.4 KiB 4 48 KiB 0 99 GiB
default.rgw.log 5 32 3.6 KiB 183 408 KiB 0 99 GiB
default.rgw.control 6 32 0 B 9 0 B 0 99 GiB
default.rgw.meta 7 32 2.6 KiB 18 168 KiB 0 99 GiB
user1@r444-22:~/ceph6/build$ ./bin/ceph auth get client.rgw.8000
*** DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
2024-01-23T14:00:40.714-0500 7fea60c67700 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:00:40.742-0500 7fea60c67700 -1 WARNING: all dangerous and experimental features are enabled.
[client.rgw.8000]
key = AQCrDLBl04rVNBAAYwaEZBqgzrLnttZdxI2pJw==
caps osd = "allow rwx tag rgw *=*"
user1@r444-22:~/ceph6/build$ s3cmd --no-ssl -c /home/user1/s3cmd/s3.cfg mb s3://bucketraw
Bucket 's3://bucketraw/' created
user1@r444-22:~/ceph6/build$ python3 /home/user1/s3test_boto.py
bucketewqppop 2024-01-23T19:01:58.228Z
bucketraw 2024-01-23T19:01:25.040Z
user1@r444-22:~/ceph6/build$ ./bin/radosgw-admin bucket list
2024-01-23T14:02:03.907-0500 7fa196208e80 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:02:03.915-0500 7fa196208e80 -1 WARNING: all dangerous and experimental features are enabled.
2024-01-23T14:02:03.919-0500 7fa196208e80 -1 WARNING: all dangerous and experimental features are enabled.
[
"bucketraw",
"bucketewqppop"
]
RGW daemon logs for bucket 'bucketraw' creation :
2024-01-23T14:01:24.123-0500 7f0fec835700 2 rgw data changes log: RGWDataChangesLog::ChangesRenewThread: start
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 CONTENT_LENGTH=0
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 HTTP_ACCEPT_ENCODING=identity
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 HTTP_AUTHORIZATION=AWS 0555b35654ad1656d804:+z4dIn/Rxb4VkIbhfjMrQ9hWFcw=
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 HTTP_HOST=10.0.0.231:8000
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 HTTP_VERSION=1.1
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 HTTP_X_AMZ_DATE=Tue, 23 Jan 2024 19:01:24 +0000
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 REMOTE_ADDR=10.0.0.231
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 REQUEST_METHOD=PUT
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 REQUEST_URI=/bucketraw/
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 SCRIPT_URI=/bucketraw/
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 SERVER_PORT=8000
2024-01-23T14:01:24.999-0500 7f0fde5d3700 1 ====== starting new request req=0x7f0edcbcf660 =====
2024-01-23T14:01:24.999-0500 7f0fde5d3700 2 req 18290115387273013000 0.000000000s initializing for trans_id = tx00000fdd38b0a1f506708-0065b00d04-4188-default
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s rgw api priority: s3=8 s3website=7
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s host=10.0.0.231
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 req 18290115387273013000 0.000000000s subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 req 18290115387273013000 0.000000000s final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/bucketraw/
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 req 18290115387273013000 0.000000000s get_handler handler=25RGWHandler_REST_Bucket_S3
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s meta>> HTTP_X_AMZ_DATE
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s x>> x-amz-date:Tue, 23 Jan 2024 19:01:24 +0000
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s handler=25RGWHandler_REST_Bucket_S3
2024-01-23T14:01:24.999-0500 7f0fde5d3700 2 req 18290115387273013000 0.000000000s getting op 1
2024-01-23T14:01:24.999-0500 7f0fde5d3700 10 req 18290115387273013000 0.000000000s cache get: name=default.rgw.log++script.prerequest. : miss
2024-01-23T14:01:24.999-0500 7f0fde5d3700 20 req 18290115387273013000 0.000000000s rados->read ofs=0 len=0
2024-01-23T14:01:25.003-0500 7f0fde5d3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:900 5.3 5:c14cb721:::script.prerequest.:head [read 0~0] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e71) v8 -- 0x5606f471a000 con 0x5606ed33d200
2024-01-23T14:01:25.003-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 134 ==== osd_op_reply(900 script.prerequest. [read 0~0] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 162+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s rados_obj.operate() r=-2 bl.length=0
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s cache put: name=default.rgw.log++script.prerequest. info.flags=0x0
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s adding default.rgw.log++script.prerequest. to cache LRU end
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s s3:create_bucket scheduling with throttler client=3 cost=1
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s s3:create_bucket op=27RGWCreateBucket_ObjStore_S3
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 2 req 18290115387273013000 0.004000045s s3:create_bucket verifying requester
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s s3:create_bucket rgw::auth::StrategyRegistry::s3_main_strategy_t: trying rgw::auth::s3::AWSAuthStrategy
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s s3:create_bucket rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::S3AnonymousEngine
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s s3:create_bucket rgw::auth::s3::S3AnonymousEngine denied with reason=-1
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s s3:create_bucket rgw::auth::s3::AWSAuthStrategy: trying rgw::auth::s3::LocalEngine
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s get_canon_resource(): dest=/bucketraw/
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s string_to_sign:
PUT
x-amz-date:Tue, 23 Jan 2024 19:01:24 +0000
/bucketraw/
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 10 req 18290115387273013000 0.004000045s s3:create_bucket cache get: name=default.rgw.meta+users.keys+0555b35654ad1656d804 : miss
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 20 req 18290115387273013000 0.004000045s s3:create_bucket rados->read ofs=0 len=0
2024-01-23T14:01:25.003-0500 7f0fd8dc8700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:901 7.11 7:8caedb2a:users.keys::0555b35654ad1656d804:head [stat,read 0~0] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e71) v8 -- 0x5606f471a380 con 0x5606ed33cd80
2024-01-23T14:01:25.003-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 728 ==== osd_map(72..72 src has 1..72) v4 ==== 615+0+0 (crc 0 0 0) 0x5606f2258fc0 con 0x5606ed33cd80
2024-01-23T14:01:25.003-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 729 ==== osd_op_reply(901 0555b35654ad1656d804 [stat out=16b,read 0~10 out=10b] v0'0 uv3 ondisk = 0) v8 ==== 206+0+26 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:25.003-0500 7f0fd7dc6700 20 req 18290115387273013000 0.008000089s s3:create_bucket rados_obj.operate() r=0 bl.length=10
2024-01-23T14:01:25.007-0500 7f0fd7dc6700 10 req 18290115387273013000 0.008000089s s3:create_bucket cache put: name=default.rgw.meta+users.keys+0555b35654ad1656d804 info.flags=0x5
2024-01-23T14:01:25.007-0500 7f0fd7dc6700 10 req 18290115387273013000 0.008000089s s3:create_bucket adding default.rgw.meta+users.keys+0555b35654ad1656d804 to cache LRU end
2024-01-23T14:01:25.007-0500 7f0fd7dc6700 10 req 18290115387273013000 0.008000089s s3:create_bucket cache get: name=default.rgw.meta+users.uid+testid : type miss (requested=0x11, cached=0x5)
2024-01-23T14:01:25.007-0500 7f0fd7dc6700 20 req 18290115387273013000 0.008000089s s3:create_bucket rados->read ofs=0 len=0
2024-01-23T14:01:25.007-0500 7f0fd7dc6700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:902 7.13 7:cab2a603:users.uid::testid:head [call version.read in=11b,read 0~0] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e72) v8 -- 0x5606f471a700 con 0x5606ed33d200
2024-01-23T14:01:25.031-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 135 ==== osd_op_reply(902 testid [call out=48b,read 0~405 out=405b] v0'0 uv1 ondisk = 0) v8 ==== 192+0+453 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:25.031-0500 7f0fd75c5700 20 req 18290115387273013000 0.032000355s s3:create_bucket rados_obj.operate() r=0 bl.length=405
2024-01-23T14:01:25.031-0500 7f0fd75c5700 10 req 18290115387273013000 0.032000355s s3:create_bucket cache put: name=default.rgw.meta+users.uid+testid info.flags=0x11
2024-01-23T14:01:25.031-0500 7f0fd75c5700 10 req 18290115387273013000 0.032000355s s3:create_bucket moving default.rgw.meta+users.uid+testid to cache LRU end
2024-01-23T14:01:25.031-0500 7f0fd75c5700 10 req 18290115387273013000 0.032000355s s3:create_bucket chain_cache_entry: cache_locator=default.rgw.meta+users.uid+testid
2024-01-23T14:01:25.031-0500 7f0fd75c5700 15 req 18290115387273013000 0.032000355s s3:create_bucket string_to_sign=PUT
x-amz-date:Tue, 23 Jan 2024 19:01:24 +0000
/bucketraw/
2024-01-23T14:01:25.031-0500 7f0fd75c5700 15 req 18290115387273013000 0.032000355s s3:create_bucket server signature=+z4dIn/Rxb4VkIbhfjMrQ9hWFcw=
2024-01-23T14:01:25.031-0500 7f0fd75c5700 15 req 18290115387273013000 0.032000355s s3:create_bucket client signature=+z4dIn/Rxb4VkIbhfjMrQ9hWFcw=
2024-01-23T14:01:25.031-0500 7f0fd75c5700 15 req 18290115387273013000 0.032000355s s3:create_bucket compare=0
2024-01-23T14:01:25.031-0500 7f0fd75c5700 20 req 18290115387273013000 0.032000355s s3:create_bucket rgw::auth::s3::LocalEngine granted access
2024-01-23T14:01:25.031-0500 7f0fd75c5700 20 req 18290115387273013000 0.032000355s s3:create_bucket rgw::auth::s3::AWSAuthStrategy granted access
2024-01-23T14:01:25.031-0500 7f0fd75c5700 2 req 18290115387273013000 0.032000355s s3:create_bucket normalizing buckets and tenants
2024-01-23T14:01:25.031-0500 7f0fd75c5700 10 req 18290115387273013000 0.032000355s s->object=<NULL> s->bucket=bucketraw
2024-01-23T14:01:25.031-0500 7f0fd75c5700 2 req 18290115387273013000 0.032000355s s3:create_bucket init permissions
2024-01-23T14:01:25.031-0500 7f0fd75c5700 10 req 18290115387273013000 0.032000355s cache get: name=default.rgw.meta+users.uid+testid : type miss (requested=0x13, cached=0x11)
2024-01-23T14:01:25.031-0500 7f0fd75c5700 20 req 18290115387273013000 0.032000355s rados->read ofs=0 len=0
2024-01-23T14:01:25.031-0500 7f0fd75c5700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:903 7.13 7:cab2a603:users.uid::testid:head [call version.read in=11b,read 0~0,getxattrs] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e72) v8 -- 0x5606f471aa80 con 0x5606ed33d200
2024-01-23T14:01:25.031-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 136 ==== osd_op_reply(903 testid [call out=48b,read 0~405 out=405b,getxattrs out=75b] v0'0 uv1 ondisk = 0) v8 ==== 234+0+528 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:25.031-0500 7f0fdadcc700 20 req 18290115387273013000 0.032000355s rados_obj.operate() r=0 bl.length=405
2024-01-23T14:01:25.031-0500 7f0fdadcc700 10 req 18290115387273013000 0.032000355s cache put: name=default.rgw.meta+users.uid+testid info.flags=0x13
2024-01-23T14:01:25.031-0500 7f0fdadcc700 10 req 18290115387273013000 0.032000355s moving default.rgw.meta+users.uid+testid to cache LRU end
2024-01-23T14:01:25.031-0500 7f0fdadcc700 10 req 18290115387273013000 0.032000355s updating xattr: name=ceph.objclass.version bl.length()=42
2024-01-23T14:01:25.031-0500 7f0fdadcc700 2 req 18290115387273013000 0.032000355s s3:create_bucket recalculating target
2024-01-23T14:01:25.031-0500 7f0fdadcc700 2 req 18290115387273013000 0.032000355s s3:create_bucket reading permissions
2024-01-23T14:01:25.031-0500 7f0fdadcc700 2 req 18290115387273013000 0.032000355s s3:create_bucket init op
2024-01-23T14:01:25.031-0500 7f0fdadcc700 2 req 18290115387273013000 0.032000355s s3:create_bucket verifying op mask
2024-01-23T14:01:25.031-0500 7f0fdadcc700 20 req 18290115387273013000 0.032000355s s3:create_bucket required_mask= 2 user.op_mask=7
2024-01-23T14:01:25.031-0500 7f0fdadcc700 2 req 18290115387273013000 0.032000355s s3:create_bucket verifying op permissions
2024-01-23T14:01:25.031-0500 7f0fdadcc700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:904 7.4 7:24c867eb:users.uid::testid.buckets:head [call user.list_buckets in=34b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e72) v8 -- 0x5606f471ae00 con 0x5606ed33d200
2024-01-23T14:01:25.035-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 137 ==== osd_op_reply(904 testid.buckets [call out=15b] v0'0 uv20 ondisk = 0) v8 ==== 158+0+15 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 2 req 18290115387273013000 0.036000401s s3:create_bucket verifying op params
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 2 req 18290115387273013000 0.036000401s s3:create_bucket pre-executing
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 2 req 18290115387273013000 0.036000401s s3:create_bucket check rate limiting
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 2 req 18290115387273013000 0.036000401s s3:create_bucket executing
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 5 req 18290115387273013000 0.036000401s s3:create_bucket NOTICE: call to do_aws4_auth_completion
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 20 req 18290115387273013000 0.036000401s s3:create_bucket using zonegroup-default placement target default-placement
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 10 req 18290115387273013000 0.036000401s s3:create_bucket cache get: name=default.rgw.meta+root+bucketraw : miss
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 20 req 18290115387273013000 0.036000401s s3:create_bucket rados->read ofs=0 len=0
2024-01-23T14:01:25.035-0500 7f0fd6dc4700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:905 7.8 7:115f62da:root::bucketraw:head [call version.read in=11b,read 0~0] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e72) v8 -- 0x5606f4528000 con 0x5606ed33cd80
2024-01-23T14:01:25.035-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 730 ==== osd_op_reply(905 bucketraw [call,read 0~0] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 195+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:25.035-0500 7f0fd65c3700 20 req 18290115387273013000 0.036000401s s3:create_bucket rados_obj.operate() r=-2 bl.length=0
2024-01-23T14:01:25.035-0500 7f0fd65c3700 10 req 18290115387273013000 0.036000401s s3:create_bucket cache put: name=default.rgw.meta+root+bucketraw info.flags=0x0
2024-01-23T14:01:25.035-0500 7f0fd65c3700 10 req 18290115387273013000 0.036000401s s3:create_bucket adding default.rgw.meta+root+bucketraw to cache LRU end
2024-01-23T14:01:25.035-0500 7f0fd65c3700 10 req 18290115387273013000 0.036000401s s3:create_bucket user=testid bucket=:bucketraw[])
2024-01-23T14:01:25.035-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_get_version(what=osdmap handle=1) v1 -- 0x5606ed2b7a20 con 0x5606ed33d680
2024-01-23T14:01:25.035-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 22 ==== mon_get_version_reply(handle=1 version=72) v2 ==== 24+0+0 (secure 0 0 0) 0x5606ed2b7a20 con 0x5606ed33d680
2024-01-23T14:01:25.035-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- pool_op(create pool 0 tid 906 name default.rgw.buckets.index v0) v4 -- 0x5606f22fdd40 con 0x5606ed33d680
2024-01-23T14:01:25.639-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 23 ==== pool_op_reply(tid 906 (0) Success v73) v1 ==== 43+0+0 (secure 0 0 0) 0x5606f22fdd40 con 0x5606ed33d680
2024-01-23T14:01:25.639-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_subscribe({osdmap=73}) v3 -- 0x5606f20ee1a0 con 0x5606ed33d680
2024-01-23T14:01:25.643-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 24 ==== osd_map(73..73 src has 1..73) v4 ==== 652+0+0 (secure 0 0 0) 0x5606f2258e00 con 0x5606ed33d680
2024-01-23T14:01:25.643-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_command({"prefix": "osd pool application enable","pool": "default.rgw.buckets.index","app": "rgw"} v 0) v1 -- 0x5606f4492f00 con 0x5606ed33d680
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:907 6.0 6:05bf5b68:::notify.1:head [watch ping cookie 94587749384192 gen 1] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fc380 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:908 6.3 6:c609908c:::notify.5:head [watch ping cookie 94587831888128 gen 1] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fc700 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:909 6.9 6:93e5b521:::notify.7:head [watch ping cookie 94587831890432 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fca80 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:910 5.4 5:22d26bf9:::data_loggenerations_metadata:head [watch ping cookie 94587831891584 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fce00 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:911 5.5 5:a60f9269:lc::lua_package_allowlist:head [watch ping cookie 94587831895040 gen 3] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fd180 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:912 6.e 6:7759931f:::notify.3:head [watch ping cookie 94587749398016 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fd500 con 0x5606f22b8000
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:913 6.d 6:b4812045:::notify.4:head [watch ping cookie 94587831886976 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fd880 con 0x5606f22b8000
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:914 6.1f 6:f95f44c2:::notify.0:head [watch ping cookie 94587749385344 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f46fdc00 con 0x5606ed33cd80
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:915 6.15 6:a93a5511:::notify.2:head [watch ping cookie 94587749396864 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f471a000 con 0x5606ed33cd80
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:916 6.14 6:2b04a3e9:::notify.6:head [watch ping cookie 94587831889280 gen 2] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e73) v8 -- 0x5606f471a700 con 0x5606ed33cd80
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_subscribe({osdmap=74}) v3 -- 0x5606f22fd520 con 0x5606ed33d680
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- ping magic: 0 v1 -- 0x5606ed2e1b80 con 0x5606ed33d200
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- ping magic: 0 v1 -- 0x5606ed2e08c0 con 0x5606ed33cd80
2024-01-23T14:01:26.075-0500 7f0fff85b700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- ping magic: 0 v1 -- 0x5606ed2e0000 con 0x5606f22b8000
2024-01-23T14:01:26.079-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 64 ==== osd_op_reply(913 notify.4 [watch ping cookie 94587831886976 gen 2] v0'0 uv145 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:26.079-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 65 ==== osd_op_reply(912 notify.3 [watch ping cookie 94587749398016 gen 2] v0'0 uv143 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:26.079-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 731 ==== osd_op_reply(915 notify.2 [watch ping cookie 94587749396864 gen 2] v0'0 uv141 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:26.079-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 732 ==== osd_op_reply(914 notify.0 [watch ping cookie 94587749385344 gen 2] v0'0 uv137 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:26.079-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 733 ==== osd_op_reply(916 notify.6 [watch ping cookie 94587831889280 gen 2] v0'0 uv149 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:26.079-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 138 ==== osd_op_reply(908 notify.5 [watch ping cookie 94587831888128 gen 1] v0'0 uv147 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:26.079-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 139 ==== osd_op_reply(907 notify.1 [watch ping cookie 94587749384192 gen 1] v0'0 uv139 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:26.079-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 140 ==== osd_op_reply(909 notify.7 [watch ping cookie 94587831890432 gen 2] v0'0 uv151 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:26.079-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 141 ==== osd_op_reply(910 data_loggenerations_metadata [watch ping cookie 94587831891584 gen 2] v0'0 uv2 ondisk = 0) v8 ==== 172+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:26.079-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 142 ==== osd_op_reply(911 lua_package_allowlist [watch ping cookie 94587831895040 gen 3] v0'0 uv397 ondisk = 0) v8 ==== 165+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:26.291-0500 7f0fdf5d5700 10 lua background: cache get: name=default.rgw.log++script.background. : hit (negative entry)
2024-01-23T14:01:26.363-0500 7f0ffd857700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6800/1325508435,v1:10.0.0.231:6801/1325508435] -- mgrreport(rgw.4188 +0-0 packed 542 status=1) v9 -- 0x5606f46fa700 con 0x5606f21ea000
2024-01-23T14:01:26.647-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 25 ==== mon_command_ack([{"prefix": "osd pool application enable","pool": "default.rgw.buckets.index","app": "rgw"}]=0 enabled application 'rgw' on pool 'default.rgw.buckets.index' v74) v1 ==== 185+0+0 (secure 0 0 0) 0x5606f22fd520 con 0x5606ed33d680
2024-01-23T14:01:26.647-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_get_version(what=osdmap handle=2) v1 -- 0x5606ed2b7b80 con 0x5606ed33d680
2024-01-23T14:01:26.647-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 26 ==== osd_map(74..74 src has 1..74) v4 ==== 634+0+0 (secure 0 0 0) 0x5606f2258c40 con 0x5606ed33d680
2024-01-23T14:01:26.651-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 27 ==== mon_get_version_reply(handle=2 version=74) v2 ==== 24+0+0 (secure 0 0 0) 0x5606ed2b7b80 con 0x5606ed33d680
2024-01-23T14:01:26.655-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_command({"prefix": "osd pool set", "pool": "default.rgw.buckets.index", "var": "pg_autoscale_bias", "val": "4"} v 0) v1 -- 0x5606f4493080 con 0x5606ed33d680
2024-01-23T14:01:27.059-0500 7f0fe101e700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:917 5.16 5:6fe6cc47:notif::queues_list_object:head [omap-get-keys in=12b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46f4380 con 0x5606ed33cd80
2024-01-23T14:01:27.059-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 734 ==== osd_op_reply(917 queues_list_object [omap-get-keys] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 162+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:27.059-0500 7f0fe101e700 20 rgw notify: INFO: next queues processing will happen at: Tue Jan 23 14:01:57 2024
2024-01-23T14:01:27.655-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 28 ==== mon_command_ack([{"prefix": "osd pool set", "pool": "default.rgw.buckets.index", "var": "pg_autoscale_bias", "val": "4"}]=0 set pool 8 pg_autoscale_bias to 4 v75) v1 ==== 170+0+0 (secure 0 0 0) 0x5606f20ee1a0 con 0x5606ed33d680
2024-01-23T14:01:27.655-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:40145/0,v1:10.0.0.231:40146/0] -- mon_command({"prefix": "osd pool set", "pool": "default.rgw.buckets.index", "var": "recovery_priority": "5"} v 0) v1 -- 0x5606f4493200 con 0x5606ed33d680
2024-01-23T14:01:27.659-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== mon.0 v2:10.0.0.231:40145/0 29 ==== mon_command_ack([{"prefix": "osd pool set", "pool": "default.rgw.buckets.index", "var": "recovery_priority": "5"}]=-22 unparseable JSON {"prefix": "osd pool set", "pool": "default.rgw.buckets.index", "var": "recovery_priority": "5"} v0) v1 ==== 243+0+0 (secure 0 0 0) 0x5606f22fd380 con 0x5606ed33d680
2024-01-23T14:01:27.659-0500 7f0fd65c3700 10 req 18290115387273013000 2.660029650s s3:create_bucket rgw_init_ioctx warning: failed to set recovery_priority on default.rgw.buckets.index
2024-01-23T14:01:27.659-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:918 8.0 8:c7864461:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.0:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46e6a80 con 0x5606f22b8000
2024-01-23T14:01:27.659-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:919 8.0 8:5a3cf1e6:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.1:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46e6380 con 0x5606f22b8000
2024-01-23T14:01:27.659-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:920 8.0 8:3f799797:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.2:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46e6700 con 0x5606f22b8000
2024-01-23T14:01:27.659-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:921 8.0 8:e35326d8:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.3:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46b8000 con 0x5606f22b8000
2024-01-23T14:01:27.659-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:922 8.0 8:b53e378b:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.4:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46f5180 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:923 8.0 8:c2f68d46:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.5:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46e6e00 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:924 8.0 8:a4add5cb:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.6:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46fa000 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:925 8.0 8:942eb740:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.7:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46fb500 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:926 8.0 8:b2a3659c:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.8:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46fa380 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:927 8.0 8:262b4566:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.9:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46d1c00 con 0x5606f22b8000
2024-01-23T14:01:27.663-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:928 8.0 8:91d4cc46:::.dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.10:head [create,call rgw.bucket_init_index in=20b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e74) v8 -- 0x5606f46fd500 con 0x5606f22b8000
2024-01-23T14:01:27.671-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 66 ==== osd_op_reply(918 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.0 [create,call] v74'1 uv1 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.671-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 67 ==== osd_op_reply(919 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.1 [create,call] v74'2 uv2 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.675-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 68 ==== osd_op_reply(920 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.2 [create,call] v74'3 uv3 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.675-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 69 ==== osd_op_reply(921 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.3 [create,call] v74'4 uv4 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.675-0500 7f0fff05a700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 70 ==== osd_map(75..75 src has 1..75) v4 ==== 642+0+0 (crc 0 0 0) 0x5606ed2bdc00 con 0x5606f22b8000
2024-01-23T14:01:27.687-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 71 ==== osd_op_reply(922 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.4 [create,call] v75'5 uv5 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.687-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 72 ==== osd_op_reply(923 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.5 [create,call] v75'6 uv6 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.687-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 73 ==== osd_op_reply(924 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.6 [create,call] v75'7 uv7 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.691-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 74 ==== osd_op_reply(925 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.7 [create,call] v75'8 uv8 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.691-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 75 ==== osd_op_reply(926 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.8 [create,call] v75'9 uv9 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.691-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 76 ==== osd_op_reply(927 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.9 [create,call] v75'10 uv10 ondisk = 0) v8 ==== 236+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.691-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 77 ==== osd_op_reply(928 .dir.3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1.10 [create,call] v75'11 uv11 ondisk = 0) v8 ==== 237+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.691-0500 7f0fd65c3700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:929 7.7 7:e440d8e6:root::.bucket.meta.bucketraw%3a3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1:head [create,call version.set in=58b,writefull 0~359 in=359b,setxattr user.rgw.acl (147) in=159b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46fd880 con 0x5606f22b8000
2024-01-23T14:01:27.695-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 78 ==== osd_op_reply(929 .bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1 [create,call,writefull 0~359,setxattr (147)] v75'21 uv21 ondisk = 0) v8 ==== 336+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.695-0500 7f0fd95c9700 10 req 18290115387273013000 2.696029902s s3:create_bucket cache put: name=default.rgw.meta+root+.bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1 info.flags=0x17
2024-01-23T14:01:27.695-0500 7f0fd95c9700 10 req 18290115387273013000 2.696029902s s3:create_bucket adding default.rgw.meta+root+.bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1 to cache LRU end
2024-01-23T14:01:27.695-0500 7f0fd95c9700 10 req 18290115387273013000 2.696029902s s3:create_bucket updating xattr: name=user.rgw.acl bl.length()=147
2024-01-23T14:01:27.695-0500 7f0fd95c9700 10 req 18290115387273013000 2.696029902s s3:create_bucket distributing notification oid=default.rgw.control:notify.3 cni=[op: 0, obj: default.rgw.meta:root:.bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1, ofs0, ns]
2024-01-23T14:01:27.695-0500 7f0fd95c9700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:930 6.e 6:7759931f:::notify.3:head [notify cookie 94587832734208 in=772b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46b8000 con 0x5606f22b8000
2024-01-23T14:01:27.695-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 79 ==== watch-notify(notify (1) cookie 94587749398016 notify 322122547200 ret 0) v3 ==== 802+0+0 (crc 0 0 0) 0x5606f47301a0 con 0x5606f22b8000
2024-01-23T14:01:27.695-0500 7f100005c700 10 rgw watcher librados: RGWWatcher::handle_notify() notify_id 322122547200 cookie 94587749398016 notifier 4188 bl.length()=760
2024-01-23T14:01:27.695-0500 7f100005c700 10 rgw watcher librados: cache put: name=default.rgw.meta+root+.bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1 info.flags=0x17
2024-01-23T14:01:27.695-0500 7f100005c700 10 rgw watcher librados: moving default.rgw.meta+root+.bucket.meta.bucketraw:3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1 to cache LRU end
2024-01-23T14:01:27.695-0500 7f100005c700 10 rgw watcher librados: updating xattr: name=user.rgw.acl bl.length()=147
2024-01-23T14:01:27.695-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 80 ==== osd_op_reply(930 notify.3 [notify cookie 94587832734208 out=8b] v0'0 uv143 ondisk = 0) v8 ==== 152+0+8 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.695-0500 7f100005c700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:931 6.e 6:7759931f:::notify.3:head [notify-ack in=20b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46f5180 con 0x5606f22b8000
2024-01-23T14:01:27.699-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 81 ==== osd_op_reply(931 notify.3 [notify-ack] v0'0 uv143 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.699-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 82 ==== watch-notify(notify_complete (2) cookie 94587832734208 notify 322122547200 ret 0) v3 ==== 42+0+48 (crc 0 0 0) 0x5606f4730340 con 0x5606f22b8000
2024-01-23T14:01:27.699-0500 7f0fd5dc2700 20 req 18290115387273013000 2.700029850s s3:create_bucket handle_bi_update(): bucket=:bucketraw[3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1]): orig_sources= new_sources=
2024-01-23T14:01:27.699-0500 7f0fd5dc2700 20 req 18290115387273013000 2.700029850s s3:create_bucket handle_bi_update(): bucket=:bucketraw[3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1]): potential sources added=[] removed=[]
2024-01-23T14:01:27.699-0500 7f0fd5dc2700 20 req 18290115387273013000 2.700029850s s3:create_bucket handle_bi_update(): bucket=:bucketraw[3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1]): orig_dests= new_dests=
2024-01-23T14:01:27.699-0500 7f0fd5dc2700 20 req 18290115387273013000 2.700029850s s3:create_bucket handle_bi_update(): bucket=:bucketraw[3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1]): potential dests added=[] removed=[]
2024-01-23T14:01:27.699-0500 7f0fd5dc2700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6818/1184109760,v1:10.0.0.231:6819/1184109760] -- osd_op(unknown.0.0:932 7.8 7:115f62da:root::bucketraw:head [create,call version.set in=58b,writefull 0~175 in=175b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46e6a80 con 0x5606ed33cd80
2024-01-23T14:01:27.703-0500 7f1004865700 1 -- 10.0.0.231:0/397118066 <== osd.2 v2:10.0.0.231:6818/1184109760 735 ==== osd_op_reply(932 bucketraw [create,call,writefull 0~175] v75'21 uv21 ondisk = 0) v8 ==== 237+0+0 (crc 0 0 0) 0x5606f2214480 con 0x5606ed33cd80
2024-01-23T14:01:27.703-0500 7f0fd55c1700 10 req 18290115387273013000 2.704030037s s3:create_bucket cache put: name=default.rgw.meta+root+bucketraw info.flags=0x17
2024-01-23T14:01:27.703-0500 7f0fd55c1700 10 req 18290115387273013000 2.704030037s s3:create_bucket moving default.rgw.meta+root+bucketraw to cache LRU end
2024-01-23T14:01:27.703-0500 7f0fd55c1700 10 req 18290115387273013000 2.704030037s s3:create_bucket distributing notification oid=default.rgw.control:notify.5 cni=[op: 0, obj: default.rgw.meta:root:bucketraw, ofs0, ns]
2024-01-23T14:01:27.703-0500 7f0fd55c1700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:933 6.3 6:c609908c:::notify.5:head [notify cookie 94587832735360 in=364b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46e6380 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 143 ==== watch-notify(notify (1) cookie 94587831888128 notify 322122547215 ret 0) v3 ==== 394+0+0 (crc 0 0 0) 0x5606f20f1040 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f100085d700 10 rgw watcher librados: RGWWatcher::handle_notify() notify_id 322122547215 cookie 94587831888128 notifier 4188 bl.length()=352
2024-01-23T14:01:27.703-0500 7f100085d700 10 rgw watcher librados: cache put: name=default.rgw.meta+root+bucketraw info.flags=0x17
2024-01-23T14:01:27.703-0500 7f100085d700 10 rgw watcher librados: moving default.rgw.meta+root+bucketraw to cache LRU end
2024-01-23T14:01:27.703-0500 7f100085d700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:934 6.3 6:c609908c:::notify.5:head [notify-ack in=20b] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46e6700 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 144 ==== osd_op_reply(933 notify.5 [notify cookie 94587832735360 out=8b] v0'0 uv147 ondisk = 0) v8 ==== 152+0+8 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 145 ==== osd_op_reply(934 notify.5 [notify-ack] v0'0 uv147 ondisk = 0) v8 ==== 152+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 146 ==== watch-notify(notify_complete (2) cookie 94587832735360 notify 322122547215 ret 0) v3 ==== 42+0+48 (crc 0 0 0) 0x5606f20f11e0 con 0x5606ed33d200
2024-01-23T14:01:27.703-0500 7f0fd4dc0700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6802/2841078876,v1:10.0.0.231:6803/2841078876] -- osd_op(unknown.0.0:935 7.4 7:24c867eb:users.uid::testid.buckets:head [call user.set_buckets_info in=211b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46e6e00 con 0x5606ed33d200
2024-01-23T14:01:27.707-0500 7f1005066700 1 -- 10.0.0.231:0/397118066 <== osd.0 v2:10.0.0.231:6802/2841078876 147 ==== osd_op_reply(935 testid.buckets [call] v75'21 uv21 ondisk = 0) v8 ==== 158+0+0 (crc 0 0 0) 0x5606f220dd40 con 0x5606ed33d200
2024-01-23T14:01:27.707-0500 7f0fd45bf700 20 req 18290115387273013000 2.708030224s s3:create_bucket Bucket::create() returned ret=0 bucket=:bucketraw[3ef4494c-500a-4f4b-a2d9-3d42ec61af30.4188.1])
2024-01-23T14:01:27.707-0500 7f0fd45bf700 2 req 18290115387273013000 2.708030224s s3:create_bucket completing
2024-01-23T14:01:27.707-0500 7f0fd45bf700 10 req 18290115387273013000 2.708030224s cache get: name=default.rgw.log++script.postrequest. : miss
2024-01-23T14:01:27.707-0500 7f0fd45bf700 20 req 18290115387273013000 2.708030224s rados->read ofs=0 len=0
2024-01-23T14:01:27.707-0500 7f0fd45bf700 1 -- 10.0.0.231:0/397118066 --> [v2:10.0.0.231:6810/3879895242,v1:10.0.0.231:6811/3879895242] -- osd_op(unknown.0.0:936 5.1f 5:fb11263f:::script.postrequest.:head [read 0~0] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e75) v8 -- 0x5606f46fa700 con 0x5606f22b8000
2024-01-23T14:01:27.707-0500 7f1005867700 1 -- 10.0.0.231:0/397118066 <== osd.1 v2:10.0.0.231:6810/3879895242 83 ==== osd_op_reply(936 script.postrequest. [read 0~0] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 163+0+0 (crc 0 0 0) 0x5606ed3e2fc0 con 0x5606f22b8000
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 20 req 18290115387273013000 2.708030224s rados_obj.operate() r=-2 bl.length=0
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 10 req 18290115387273013000 2.708030224s cache put: name=default.rgw.log++script.postrequest. info.flags=0x0
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 10 req 18290115387273013000 2.708030224s adding default.rgw.log++script.postrequest. to cache LRU end
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 2 req 18290115387273013000 2.708030224s s3:create_bucket op status=0
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 2 req 18290115387273013000 2.708030224s s3:create_bucket http status=200
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 1 ====== req done req=0x7f0edcbcf660 op status=0 http_status=200 latency=2.708030224s ======
2024-01-23T14:01:27.707-0500 7f0fd3dbe700 1 beast: 0x7f0edcbcf660: 10.0.0.231 - testid [23/Jan/2024:14:01:24.999 -0500] "PUT /bucketraw/ HTTP/1.1" 200 0 - - - latency=2.708030224s
Actions