From these:
crt=5395'481460 lcod 5395'481461 mlcod 5395'481461 active+clean] do_osd_op
sync_read 4096~1024
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] read got 1024 / 1024 bytes from obj 5:9a6dd8c0:gc::gc.0:head
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] method called response length=0
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_ops error: (22) Invalid argument
I suspect that there is an error while reading the queue head data, but to
debug that further, I need rgw logs and osd logs at debug level 20,
specifically debug_objclass=20 on osds.
Although you have mentioned that you installed a new Ceph cluster with
Octopus v15.2.1, but just wanted to make sure that rgw, and osd versions
are the same - 15.2.1?
Thanks,
Pritha
On Wed, May 6, 2020 at 12:26 PM James, GleSYS <james.mcewan(a)glesys.se>
wrote:
Hi,
Yes, it’s the same error with “—include-all”. I am currently awaiting
confirmation of my account creation on the tracker site.
In the meantime, here are some logs which I’ve obtained:
radosgw-admin gc list --debug-rgw=10 --debug-ms=10:
2020-05-06T06:06:33.922+0000 7ff4ccffb700 1 --
[2a00:X:X:6::4]:0/232669402 <== osd.2 v2:[2a00:X:X:6::15]:6804/216047 2
==== osd_op_reply(32 gc.31 [create,call,call,call] v5395'1345263 uv1345179
ondisk = -125 ((125) Operation canceled)) v8 ==== 275+0+0 (crc 0 0 0)
0x7ff4c4076af0 con 0x55ca738cd010
2020-05-06T06:06:33.922+0000 7ff4ccffb700 10 --
[2a00:X:X:6::4]:0/232669402 dispatch_throttle_release 275 to dispatch
throttler 275/104857600
2020-05-06T06:06:33.922+0000 7ff4e0111080 1 --
[2a00:X:X:6::4]:0/232669402 -->
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606] --
osd_op(unknown.0.0:33 5.9 5:9a6dd8c0:gc::gc.0:head [call rgw.gc_list
in=25b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8 --
0x55ca73935790 con 0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4e0111080 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).send_message enqueueing message m=0x55ca73935790 type=42
osd_op(client.610887.0:33 5.9 5:9a6dd8c0:gc::gc.0:head [call rgw.gc_list
in=25b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1).handle_write
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_event
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending message m=0x55ca73935790 seq=4
osd_op(client.610887.0:33 5.9 5:9a6dd8c0:gc::gc.0:head [call rgw.gc_list
in=25b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1)._try_send sent bytes 330 remaining
bytes 0
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending 0x55ca73935790 done.
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=41 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=148 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=0 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=15 align=4096
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_read_frame_dispatch tag=17
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_message got 148 + 0 + 15 byte message. envelope type=43
src osd.15 off 0
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READ_MESSAGE_COMPLETE pgs=23
cs=0 l=1 rx=0 tx=0).handle_message received message m=0x7ff4c0007110 seq=4
from=osd.15 type=43 osd_op_reply(33 gc.0 [call out=15b] v0'0 uv481420
ondisk = 0) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 1 --
[2a00:X:X:6::4]:0/232669402 <== osd.15 v2:[2a00:X:X:6::18]:6800/383606 4
==== osd_op_reply(33 gc.0 [call out=15b] v0'0 uv481420 ondisk = 0) v8 ====
148+0+15 (crc 0 0 0) 0x7ff4c0007110 con 0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 dispatch_throttle_release 163 to dispatch
throttler 163/104857600
2020-05-06T06:06:33.922+0000 7ff4e0111080 1 --
[2a00:X:X:6::4]:0/232669402 -->
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606] --
osd_op(unknown.0.0:34 5.9 5:9a6dd8c0:gc::gc.0:head [call version.read
in=11b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8 --
0x55ca73934780 con 0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4e0111080 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).send_message enqueueing message m=0x55ca73934780 type=42
osd_op(client.610887.0:34 5.9 5:9a6dd8c0:gc::gc.0:head [call version.read
in=11b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1).handle_write
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_event
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending message m=0x55ca73934780 seq=5
osd_op(client.610887.0:34 5.9 5:9a6dd8c0:gc::gc.0:head [call version.read
in=11b] snapc 0=[] ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1)._try_send sent bytes 316 remaining
bytes 0
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending 0x55ca73934780 done.
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=41 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=148 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=0 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=24 align=4096
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_read_frame_dispatch tag=17
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_message got 148 + 0 + 24 byte message. envelope type=43
src osd.15 off 0
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READ_MESSAGE_COMPLETE pgs=23
cs=0 l=1 rx=0 tx=0).handle_message received message m=0x7ff4c0007110 seq=5
from=osd.15 type=43 osd_op_reply(34 gc.0 [call out=24b] v0'0 uv481420
ondisk = 0) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 1 --
[2a00:X:X:6::4]:0/232669402 <== osd.15 v2:[2a00:X:X:6::18]:6800/383606 5
==== osd_op_reply(34 gc.0 [call out=24b] v0'0 uv481420 ondisk = 0) v8 ====
148+0+24 (crc 0 0 0) 0x7ff4c0007110 con 0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 dispatch_throttle_release 172 to dispatch
throttler 172/104857600
2020-05-06T06:06:33.922+0000 7ff4e0111080 1 --
[2a00:X:X:6::4]:0/232669402 -->
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606] --
osd_op(unknown.0.0:35 5.9 5:9a6dd8c0:gc::gc.0:head [call
rgw_gc.rgw_gc_queue_list_entries in=46b] snapc 0=[]
ondisk+read+known_if_redirected e5395) v8 -- 0x55ca73935790 con
0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4e0111080 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).send_message enqueueing message m=0x55ca73935790 type=42
osd_op(client.610887.0:35 5.9 5:9a6dd8c0:gc::gc.0:head [call
rgw_gc.rgw_gc_queue_list_entries in=46b] snapc 0=[]
ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1).handle_write
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_event
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending message m=0x55ca73935790 seq=6
osd_op(client.610887.0:35 5.9 5:9a6dd8c0:gc::gc.0:head [call
rgw_gc.rgw_gc_queue_list_entries in=46b] snapc 0=[]
ondisk+read+known_if_redirected e5395) v8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 msgr2=0x55ca738a1ab0 crc :-1
s=STATE_CONNECTION_ESTABLISHED l=1)._try_send sent bytes 351 remaining
bytes 0
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).write_message sending 0x55ca73935790 done.
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=41 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READY pgs=23 cs=0 l=1 rx=0
tx=0).handle_read_frame_preamble_main got new segment: len=148 align=8
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_read_frame_dispatch tag=17
2020-05-06T06:06:33.922+0000 7ff4cbff9700 5 --2-
[2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=THROTTLE_DONE pgs=23 cs=0 l=1
rx=0 tx=0).handle_message got 148 + 0 + 0 byte message. envelope type=43
src osd.15 off 0
ERROR: failed to list objs: 2020-05-06T06:06:33.922+0000 7ff4cbff9700 5
--2- [2a00:X:X:6::4]:0/232669402 >>
[v2:[2a00:X:X:6::18]:6800/383606,v1:[2a00:X:X:6::18]:6801/383606]
conn(0x55ca7389f680 0x55ca738a1ab0 crc :-1 s=READ_MESSAGE_COMPLETE pgs=23
cs=0 l=1 rx=0 tx=0).handle_message received message m=0x7ff4c0007110 seq=6
from=osd.15 type=43 osd_op_reply(35 gc.0 [call] v0'0 uv0 ondisk = -22 ((22)
Invalid argument)) v8
(22) Invalid argument
2020-05-06T06:06:33.922+0000 7ff4cbff9700 1 --
[2a00:X:X:6::4]:0/232669402 <== osd.15 v2:[2a00:X:X:6::18]:6800/383606 6
==== osd_op_reply(35 gc.0 [call] v0'0 uv0 ondisk = -22 ((22) Invalid
argument)) v8 ==== 148+0+0 (crc 0 0 0) 0x7ff4c0007110 con 0x55ca7389f680
2020-05-06T06:06:33.922+0000 7ff4cbff9700 10 --
[2a00:X:X:6::4]:0/232669402 dispatch_throttle_release 148 to dispatch
throttler 148/104857600
2020-05-06T06:06:33.926+0000 7ff4a1fdb700 2
RGWDataChangesLog::ChangesRenewThread: start
/var/log/ceph/ceph-osd.15.log
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 5395 dequeue_op
0x555f68a5a580 prio 63 cost 46 latency 0.000009 osd_op(client.610887.0:35
5.9 5.31bb659 (undecoded) ondisk+read+known_if_redirected e5395) v8 pg
pg[5.9( v 5395'481462 (5387'478000,5395'481462] local-lis
/les=5394/5395 n=48 ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394
pruub=12.023579210s) [15,21,26] r=0 lpr=5394 crt=5395'481460 lcod
5395'481461 mlcod 5395'481461 active+clean]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] _handle_message: 0x555f68a5a580
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_op osd_op(client.610887.0:35 5.9 5:9a6dd8c0:gc::gc.0:head
[call rgw_gc.rgw_gc_queue_list_entries in=46b] snapc 0=[]
ondisk+read+known_if_redirected e5395) v8 may_read -> read-ordered flags
ondisk+read+known_if_redirected
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] get_object_context: found obc in cache: 0x555f67056dc0
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] get_object_context: 0x555f67056dc0 5:9a6dd8c0:gc::gc.0:head
rwstate(none n=0 w=0) oi: 5:9a6dd8c0:gc::gc.0:head(5395'481420
client.325552.0:1326193 dirty s 732076 uv 481420 alloc_hint [0 0 0])
exists: 1 ssc: 0x555f671f51e0 snapset: 0=[]:{}
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] find_object_context 5:9a6dd8c0:gc::gc.0:head @head
oi=5:9a6dd8c0:gc::gc.0:head(5395'481420 client.325552.0:1326193 dirty s
732076 uv 481420 alloc_hint [0 0 0])
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] execute_ctx 0x555f68255200
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] execute_ctx 5:9a6dd8c0:gc::gc.0:head [call
rgw_gc.rgw_gc_queue_list_entries in=46b] ov 5395'481420
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op 5:9a6dd8c0:gc::gc.0:head [call
rgw_gc.rgw_gc_queue_list_entries in=46b]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op call rgw_gc.rgw_gc_queue_list_entries in=46b
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] call method rgw_gc.rgw_gc_queue_list_entries
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op 5:9a6dd8c0:gc::gc.0:head [sync_read 0~1024]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op sync_read 0~1024
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] read got 1024 / 1024 bytes from obj 5:9a6dd8c0:gc::gc.0:head
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op 5:9a6dd8c0:gc::gc.0:head [sync_read 1024~3090
[fadvise_sequential]]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op sync_read 1024~3090 [fadvise_sequential]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] read got 3090 / 3090 bytes from obj 5:9a6dd8c0:gc::gc.0:head
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op 5:9a6dd8c0:gc::gc.0:head [sync_read 4096~1024]
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_op sync_read 4096~1024
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] read got 1024 / 1024 bytes from obj 5:9a6dd8c0:gc::gc.0:head
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] method called response length=0
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 pg_epoch: 5395 pg[5.9(
v 5395'481462 (5387'478000,5395'481462] local-lis/les=5394/5395 n=48
ec=67/67 lis/c=5394/5394 les/c/f=5395/5395/0 sis=5394 pruub=12.023579210s)
[15,21,26] r=0 lpr=5394 crt=5395'481460 lcod 5395'481461 mlcod 5395'481461
active+clean] do_osd_ops error: (22) Invalid argument
2020-05-06T08:06:33.925+0200 7f73b554a700 10 osd.15 5395 dequeue_op
0x555f68a5a580 finish
Can you draw any conclusions from these logs?
Regards,
James
On 6 May 2020, at 05:03, Pritha Srivastava
<prsrivas(a)redhat.com> wrote:
Hi James,
Does radosgw-admin gc list --include-all, give the same error? If yes,
can
you please open a tracker issue and share rgw and
osd logs?
Thanks,
Pritha
On Wed, May 6, 2020 at 12:22 AM James, GleSYS <james.mcewan(a)glesys.se>
wrote:
> Hi,
>
> We’ve recently installed a new Ceph cluster running Octopus 15.2.1, and
> we’re using RGW with an erasure coded backed pool.
>
> I started to get a suspicion that deleted objects were not getting
cleaned
> up properly, and I wanted to verify this by
checking the garbage
collector.
>
> That’s when I discovered that when I run “radosgw-admin gc list”, I get
> the following error:
> "ERROR: failed to list objs: (22) Invalid argument”
>
> When running the command with the debug-rgw=20 flag, I see a bit more
> information:
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=0
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=1
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=2
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=3
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=4
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=5
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=6
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 add_watcher() i=7
> 2020-05-05T18:39:19.455+0000 7f3312d82080 2 all 8 watchers are set,
> enabling cache
> 2020-05-05T18:39:19.455+0000 7f3312d82080 20 check_secure_mon_conn():
auth
registy
supported: methods=[2,1] modes=[2,1]
2020-05-05T18:39:19.455+0000 7f3312d82080 20 check_secure_mon_conn():
method 1 is insecure
2020-05-05T18:39:19.455+0000 7f32d4fd9700 2
RGWDataChangesLog::ChangesRenewThread: start
2020-05-05T18:39:19.519+0000 7f3246ffd700 20 reqs_thread_entry: start
2020-05-05T18:39:19.519+0000 7f3312d82080 20 init_complete bucket index
max shards: 11
2020-05-05T18:39:19.519+0000 7f3244ff9700 20 reqs_thread_entry: start
2020-05-05T18:39:19.519+0000 7f323affd700 20 reqs_thread_entry: start
ERROR: failed to list objs: (22) Invalid argument
2020-05-05T18:39:19.523+0000 7f32d4fd9700 2
RGWDataChangesLog::ChangesRenewThread: start
2020-05-05T18:39:19.523+0000 7f3312d82080 20 remove_watcher() i=0
2020-05-05T18:39:19.523+0000 7f3312d82080 2 removed watcher, disabling
cache
2020-05-05T18:39:19.523+0000 7f3312d82080 20 remove_watcher() i=1
2020-05-05T18:39:19.523+0000 7f3312d82080 20 remove_watcher() i=2
2020-05-05T18:39:19.527+0000 7f3312d82080 20 remove_watcher() i=3
2020-05-05T18:39:19.527+0000 7f3312d82080 20 remove_watcher() i=4
2020-05-05T18:39:19.527+0000 7f3312d82080 20 remove_watcher() i=5
2020-05-05T18:39:19.527+0000 7f3312d82080 20 remove_watcher() i=6
2020-05-05T18:39:19.527+0000 7f3312d82080 20 remove_watcher() I=7
I find very little information regarding this error, so I wondered if
someone here could help me troubleshoot the issue?
Thanks,
James.
_______________________________________________
ceph-users mailing list -- ceph-users(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io
_______________________________________________
ceph-users mailing list -- ceph-users(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io