Bug #11284
closedceph_test_rados ENOENT
0%
Description
ubuntu@teuthology:/a/samuelj-2015-03-30_17:44:44-rados-wip-sam-testing-distro-basic-multi/829532/remote
2015-03-30 19:58:16.790747 7f0c8b336700 1 -- 10.214.132.30:6808/4566 <== client.4128 10.214.132.30:0/1024613 34 ==== osd_op(client.4128.0:6721 plana4824613-16@17f [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] 2.64d2e308 ack+read+known_if_redirected e650) v5 ==== 364+0+32 (4268001709 0 2675358983) 0x654ba00 con 0x6f7c420
2015-03-30 19:58:16.791570 7f0ca7122700 1 -- 10.214.132.30:0/4566 --> 10.214.132.30:6808/4566 -- osd_op(osd.1.348:1214 plana4824613-16@17f [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] 1.64d2e308 ack+read+ignore_cache+ignore_overlay+known_if_redirected e650) v5 -- ?+0 0x70c0a00 con 0x53a9dc0
2015-03-30 19:58:16.791828 7f0c8c439700 1 -- 10.214.132.30:6808/4566 <== osd.1 10.214.132.30:0/4566 233 ==== osd_op(osd.1.348:1214 plana4824613-16@17f [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] 1.64d2e308 ack+read+ignore_cache+ignore_overlay+known_if_redirected e650) v5 ==== 364+0+32 (3671357830 0 2675358983) 0x741f500 con 0x6f7c6e0
2015-03-30 19:58:19.446417 7f0c96eeb700 1 -- 10.214.132.30:6808/4566 <== client.4128 10.214.132.30:0/1024613 9 ==== osd_op(client.4128.0:6721 plana4824613-16@17f [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] 2.64d2e308 RETRY=1 ack+retry+read+known_if_redirected e651) v5 ==== 364+0+32 (986055740 0 2675358983) 0xa820780 con 0x6f7c2c0
2015-03-30 19:58:19.447122 7f0ca491d700 1 -- 10.214.132.30:6808/4566 --> 10.214.132.30:0/1024613 -- osd_op_reply(6721 plana4824613-16 [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] v0'0 uv0 ack = 2 ((2) No such file or directory)) v6 - ?+0 0xb63ab00 con 0x6f7c2c0
2015-03-30 19:58:22.313310 7f0ca7122700 1 -- 10.214.132.30:6808/4566 --> 10.214.132.30:0/4566 -- osd_op_reply(1214 plana4824613-16 [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] v0'0 uv734 ondisk = 0) v6 -- ?+0 0x7154840 con 0x6f7c6e0
2015-03-30 19:58:22.316761 7f0c8bb37700 1 -- 10.214.132.30:0/4566 <== osd.1 10.214.132.30:6808/4566 214 ==== osd_op_reply(1214 plana4824613-16 [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] v0'0 uv734 ondisk = 0) v6 ==== 392+0+3173892 (904730137 0 1217463802) 0x77af840 con 0x53a9dc0
2015-03-30 19:58:22.330948 7f0c9f913700 1 -- 10.214.132.30:6808/4566 --> 10.214.132.30:0/1024613 -- osd_op_reply(6721 plana4824613-16 [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] v0'0 uv734 ondisk = 0) v6 -- ?+0 0xa37b580 con 0x6f7c420
Not sure what's going on yet, but it looks like the initial read op actually ends up succeeding after being proxied to the base tier. The retry, however, short circuits first with an ENOENT for some reason.
Updated by Samuel Just about 9 years ago
- Assignee set to Samuel Just
2015-03-30 19:58:16.791985 7f0ca7122700 10 osd.1 pg_epoch: 650 pg[2.0( v 649'4666 (161'1606,649'4666] local-les=614 n=50 ec=6 les/c 614/614 591/613/480) [1,5] r=0 lpr=613 crt=648'4660 lcod 649'4664 mlcod 649'4664 active+clean+scrubbing snaptrimq=[1b3~1,1c3~1]] get_object_context: 0xa140b80 64d2e308/plana4824613-16/head//2 rwstate(none n=0 w=0) oi: 64d2e308/plana4824613-16/head//2(0'0 unknown.0.0:0 wrlock_by=unknown.0.0:0 s 0 uv 0) ssc: 0x7eea870 snapset: 0=[]:[]
2015-03-30 19:58:16.792020 7f0ca7122700 10 osd.1 pg_epoch: 650 pg[2.0( v 649'4666 (161'1606,649'4666] local-les=614 n=50 ec=6 les/c 614/614 591/613/480) [1,5] r=0 lpr=613 crt=648'4660 lcod 649'4664 mlcod 649'4664 active+clean+scrubbing snaptrimq=[1b3~1,1c3~1]] promote_object 64d2e308/plana4824613-16/head//2
2015-03-30 19:58:16.792030 7f475f08e700 1 -- 10.214.133.33:0/22414 <== osd.0 10.214.132.30:6806/23286 166 ==== osd_ping(ping_reply e647 stamp 2015-03-30 19:58:16.791175) v2 ==== 47+0+0 (2769684808 0 0) 0x58a5c00 con 0x3eb2c60
2015-03-30 19:58:16.792044 7f0ca7122700 10 osd.1 pg_epoch: 650 pg[2.0( v 649'4666 (161'1606,649'4666] local-les=614 n=50 ec=6 les/c 614/614 591/613/480) [1,5] r=0 lpr=613 crt=648'4660 lcod 649'4664 mlcod 649'4664 active+clean+scrubbing snaptrimq=[1b3~1,1c3~1]] promote_object 64d2e308/plana4824613-16/head//2 blocked by scrub
2015-03-30 19:58:16.792034 7f0ca491d700 10 osd.1 650 dequeue_op 0x603ac00 prio 63 cost 32 latency 0.000295 osd_op(osd.1.348:1214 plana4824613-16@17f [read 0~3173806,omap-get-vals-by-keys 0~4,omap-get-keys 0~12,omap-get-vals 0~16,omap-get-header 0~0,getxattrs] 1.64d2e308 ack+read+ignore_cache+ignore_overlay+known_if_redirected e650) v5 pg pg[1.0( v 644'2881 (0'0,644'2881] local-les=647 n=206 ec=5 les/c 600/600 645/645/365) [1,0] r=0 lpr=645 pi=599-644/1 crt=644'2875 lcod 644'2879 mlcod 0'0 activating+degraded snaptrimq=[9b~1,1ad~1,1b3~1,1c1~3]]
2015-03-30 19:58:16.792067 7f0ca7122700 10 osd.1 pg_epoch: 650 pg[2.0( v 649'4666 (161'1606,649'4666] local-les=614 n=50 ec=6 les/c 614/614 591/613/480) [1,5] r=0 lpr=613 crt=648'4660 lcod 649'4664 mlcod 649'4664 active+clean+scrubbing snaptrimq=[1b3~1,1c3~1]] promote_object 64d2e308/plana4824613-16/head//2 no op, dropping on the floor
2015-03-30 19:58:16.792093 7f0ca7122700 10 osd.1 650 dequeue_op 0x5ef7f00 finish
2015-03-30 19:58:16.792107 7f0ca491d700 20 osd.1 pg_epoch: 650 pg[1.0( v 644'2881 (0'0,
Bug with 65bb4df599541cd2e0f195b905f24f529e255c00.
Dropping the op on the floor leaves a cached obc with obs.exists=false.