Bug #36634
Updated by Sage Weil over 5 years ago
<pre> 2018-10-30T15:03:35.632 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: [ RUN ] LibRadosWatchNotify.WatchNotify2Timeout 2018-10-30T15:03:35.632 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: watch_notify2_test_cb from 4487 notify_id 184683593730 cookie 33829680 2018-10-30T15:03:35.636 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: watch_notify2_test_errcb cookie 33829680 err -110 2018-10-30T15:03:35.636 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: watch_notify2_test_cb from 4487 notify_id 197568495619 cookie 33829680 2018-10-30T15:03:35.637 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: watch_notify2_test_cb from 4487 notify_id 201863462916 cookie 33829680 2018-10-30T15:03:35.638 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: /build/ceph-14.0.0-4682-g78efc77/src/test/librados/watch_notify.cc:684: Failure 2018-10-30T15:03:35.638 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: Expected: (rados_watch_check(ioctx, handle)) > (0), actual: -110 vs 0 2018-10-30T15:03:35.639 INFO:tasks.workunit.client.0.smithi153.stdout: api_watch_notify: [ FAILED ] LibRadosWatchNotify.WatchNotify2Timeout (6004 ms) </pre> /a/sage-2018-10-30_05:25:17-rados-wip-sage2-testing-2018-10-29-2124-distro-basic-smithi/3203140 client is remote/smithi153/log/ceph-client.admin.19840.log <pre> 2018-10-30 15:03:18.241 7fcbb6ffd700 1 -- 172.21.15.153:0/1272352374 --> 172.21.15.153:6801/13188 -- osd_op(client.4487.0:47 10.1 10:9ea975d7:test-rados-api-smithi153-19840-9::foo:head [notify cookie 34291712] snapc 0=[] ondisk+read+known_if_redirected e46) v8 -- ?+0 0x7fcbb0012d60 con 0x2045a30 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter put_session s=0x2043ef0 osd=0 7 2018-10-30 15:03:18.241 7fcbb6ffd700 5 client.4487.objecter 2 in flight 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter dump_active .. 0 homeless 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter 46 10.ebae9579 osd.0 foo [watch reconnect cookie 33829680 gen 1] 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter 47 10.ebae9579 osd.0 foo [notify cookie 34291712] 2018-10-30 15:03:18.241 7fcbb6ffd700 1 -- 172.21.15.153:0/1272352374 <== mon.0 172.21.15.67:6789/0 8 ==== osd_map(44..46 src has 1..46) v4 ==== 10286+0+0 (570398883 0 0) 0x7fcb7c000a90 con 0x7fcbb0010990 2018-10-30 15:03:18.241 7fcbb6ffd700 10 client.4487.objecter ms_dispatch 0x1f8d970 osd_map(44..46 src has 1..46) v4 2018-10-30 15:03:18.241 7fcbb6ffd700 3 client.4487.objecter handle_osd_map ignoring epochs [44,46] <= 46 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter dump_active .. 0 homeless 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter 46 10.ebae9579 osd.0 foo [watch reconnect cookie 33829680 gen 1] 2018-10-30 15:03:18.241 7fcbb6ffd700 20 client.4487.objecter 47 10.ebae9579 osd.0 foo [notify cookie 34291712] 2018-10-30 15:03:18.241 7fcbbc3a6700 1 -- 172.21.15.153:0/1272352374 <== osd.0 172.21.15.153:6801/13188 15 ==== watch-notify(notify (1) cookie 33829680 notify 197568495619 ret 0) v3 ==== 48+0+0 (3975032253 0 0) 0x7fcbac001040 con 0x2045a30 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter ms_dispatch 0x1f8d970 watch-notify(notify (1) cookie 33829680 notify 197568495619 ret 0) v3 2018-10-30 15:03:18.241 7fcbbc3a6700 1 -- 172.21.15.153:0/1272352374 <== osd.0 172.21.15.153:6801/13188 16 ==== osd_op_reply(47 foo [notify cookie 34291712] v0'0 uv4 ondisk = 0) v8 ==== 147+0+8 (1797624069 0 1046536822) 0x7fcbac001510 con 0x2045a30 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter ms_dispatch 0x1f8d970 osd_op_reply(47 foo [notify cookie 34291712] v0'0 uv4 ondisk = 0) v8 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter in handle_osd_op_reply 2018-10-30 15:03:18.241 7fcbbc3a6700 7 client.4487.objecter handle_osd_op_reply 47 ondisk uv 4 in 10.1 attempt 0 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter op 0 rval 0 len 8 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter handle_osd_op_reply completed tid 47 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter _finish_op 47 2018-10-30 15:03:18.241 7fcbbc3a6700 20 client.4487.objecter put_session s=0x2043ef0 osd=0 7 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter _session_op_remove 0 47 2018-10-30 15:03:18.241 7fcbbc3a6700 5 client.4487.objecter 1 in flight 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter _linger_commit 19 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter _linger_commit notify_id=197568495619 2018-10-30 15:03:18.241 7fcbbc3a6700 1 -- 172.21.15.153:0/1272352374 <== osd.0 172.21.15.153:6801/13188 17 ==== osd_op_reply(46 foo [watch reconnect cookie 33829680 gen 1] v46'6 uv4 ondisk = 0) v8 ==== 147+0+0 (2624072480 0 0) 0x7fcbac001510 con 0x2045a30 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter ms_dispatch 0x1f8d970 osd_op_reply(46 foo [watch reconnect cookie 33829680 gen 1] v46'6 uv4 ondisk = 0) v8 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter in handle_osd_op_reply 2018-10-30 15:03:18.241 7fcbbc3a6700 7 client.4487.objecter handle_osd_op_reply 46 ondisk uv 4 in 10.1 attempt 0 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter op 0 rval 0 len 0 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter handle_osd_op_reply completed tid 46 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter _finish_op 46 2018-10-30 15:03:18.241 7fcbbc3a6700 20 client.4487.objecter put_session s=0x2043ef0 osd=0 6 2018-10-30 15:03:18.241 7fcbbc3a6700 15 client.4487.objecter _session_op_remove 0 46 2018-10-30 15:03:18.241 7fcbbc3a6700 5 client.4487.objecter 0 in flight 2018-10-30 15:03:18.241 7fcbbc3a6700 10 client.4487.objecter _linger_reconnect 18 = 0 (last_error -110) 2018-10-30 15:03:18.245 7fcbb6ffd700 1 -- 172.21.15.153:0/1272352374 mark_down 0x7fcbb0008fe0 -- pipe dne 2018-10-30 15:03:18.245 7fcbb6ffd700 10 client.4487.objecter ms_handle_connect 0x7fcbb0005260 2018-10-30 15:03:18.453 7fcb9effd700 10 client.4487.objecter _op_submit op 0x7fcb8c003dc0 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter _calc_target epoch 46 base foo @10;test-rados-api-smithi153-19840-9 precalc_pgid 0 pgid 0.0 is_read 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter _calc_target target foo @10;test-rados-api-smithi153-19840-9 -> pgid 10.ebae9579 2018-10-30 15:03:18.453 7fcb9effd700 10 client.4487.objecter _calc_target raw pgid 10.ebae9579 -> actual 10.1 acting [0,4,7] primary 0 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter _get_session s=0x2043ef0 osd=0 5 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter note: not requesting reply 2018-10-30 15:03:18.453 7fcb9effd700 10 client.4487.objecter _op_submit oid foo '@10;test-rados-api-smithi153-19840-9' '@10;test-rados-api-smithi153-19840-9' [notify-ack cookie 0] tid 48 osd.0 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter get_session s=0x2043ef0 osd=0 5 2018-10-30 15:03:18.453 7fcb9effd700 15 client.4487.objecter _session_op_assign 0 48 2018-10-30 15:03:18.453 7fcb9effd700 15 client.4487.objecter _send_op 48 to 10.1 on osd.0 2018-10-30 15:03:18.453 7fcb9effd700 1 -- 172.21.15.153:0/1272352374 --> 172.21.15.153:6801/13188 -- osd_op(client.4487.0:48 10.1 10:9ea975d7:test-rados-api-smithi153-19840-9::foo:head [notify-ack cookie 0] snapc 0=[] ondisk+read+known_if_redirected e46) v8 -- ?+0 0x7fcb8c004220 con 0x2045a30 2018-10-30 15:03:18.453 7fcb9effd700 20 client.4487.objecter put_session s=0x2043ef0 osd=0 6 2018-10-30 15:03:18.453 7fcb9effd700 5 client.4487.objecter 0 in flight 2018-10-30 15:03:18.453 7fcb9effd700 10 librados: handle_error cookie 33829680 err -110 2018-10-30 15:03:18.453 7fcb9effd700 10 client.4487.objecter _do_watch_notify watch-notify(notify (1) cookie 33829680 notify 197568495619 ret 0) v3 2018-10-30 15:03:18.453 7fcb9effd700 10 librados: handle_notify 197568495619 cookie 33829680 notifier_id 4487 len 6 2018-10-30 15:03:18.453 7fcbbc3a6700 1 -- 172.21.15.153:0/1272352374 <== osd.0 172.21.15.153:6801/13188 18 ==== osd_op_reply(48 foo [notify-ack cookie 0] v0'0 uv4 ondisk = 0) v8 ==== 147+0+0 (2837018151 0 0) 0x7fcbac001510 con 0x2045a30 2018-10-30 15:03:18.453 7fcbbc3a6700 10 client.4487.objecter ms_dispatch 0x1f8d970 osd_op_reply(48 foo [notify-ack cookie 0] v0'0 uv4 ondisk = 0) v8 2018-10-30 15:03:18.453 7fcbbc3a6700 10 client.4487.objecter in handle_osd_op_reply 2018-10-30 15:03:18.453 7fcbbc3a6700 7 client.4487.objecter handle_osd_op_reply 48 ondisk uv 4 in 10.1 attempt 0 2018-10-30 15:03:18.453 7fcbbc3a6700 10 client.4487.objecter op 0 rval 0 len 0 2018-10-30 15:03:18.453 7fcbbc3a6700 15 client.4487.objecter handle_osd_op_reply completed tid 48 2018-10-30 15:03:18.453 7fcbbc3a6700 15 client.4487.objecter _finish_op 48 2018-10-30 15:03:18.453 7fcbbc3a6700 20 client.4487.objecter put_session s=0x2043ef0 osd=0 6 2018-10-30 15:03:18.453 7fcbbc3a6700 15 client.4487.objecter _session_op_remove 0 48 2018-10-30 15:03:18.453 7fcbbc3a6700 5 client.4487.objecter 0 in flight 2018-10-30 15:03:19.241 7fcbbc3a6700 1 -- 172.21.15.153:0/1272352374 <== osd.0 172.21.15.153:6801/13188 19 ==== watch-notify(notify_complete (2) cookie 34291712 notify 197568495619 ret -110) v3 ==== 42+0+24 (3127676839 0 35843371) 0x7fcbac000940 con 0x2045a30 2018-10-30 15:03:19.241 7fcbbc3a6700 10 client.4487.objecter ms_dispatch 0x1f8d970 watch-notify(notify_complete (2) cookie 34291712 notify 197568495619 ret -110) v3 2018-10-30 15:03:19.241 7fcbbc3a6700 10 librados: finish completed notify (linger op 0x20b4000), r = -110 </pre> it looks like it tried to do a 300s timeout but it timed out after about 2s: <pre> 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] do_osd_op notify cookie 34291712 2018-10-30 15:03:18.241 7efead3a6700 15 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] do_osd_op_effects client.4487 con 0xd612380 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] do_osd_op_effects, notify notify(cookie 34291712 notify197568495619 1s) 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] starting notify on watch 33829680,client.4487 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] -- Watch(33829680,client.4487) start_notify 197568495619 2018-10-30 15:03:18.241 7efead3a6700 10 Notify(34291712,197568495619 watchers=0) start_watcher 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 luod=43'5 crt=43'5 lcod 43'4 mlcod 0'0 active+clean] -- Watch(33829680,client.4487) send_notify 2018-10-30 15:03:18.241 7efead3a6700 1 -- 172.21.15.153:6801/13188 --> 172.21.15.153:0/1272352374 -- watch-notify(notify (1) cookie 33829680 notify 197568495619 ret 0) v3 -- ?+0 0xea20280 con 0xd612380 2018-10-30 15:03:18.241 7efead3a6700 10 Notify(34291712,197568495619 watchers=1) maybe_complete_notify -- 1 in progress watchers ... 2018-10-30 15:03:18.241 7efead3a6700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] sending commit on osd_op(client.4487.0:46 10.1 10:9ea975d7:test-rados-api-smithi153-19840-9::foo:head [watch reconnect cookie 33829680 gen 1] snapc 0=[] ondisk+write+known_if_redirected e46) v8 0xe938d80 2018-10-30 15:03:18.241 7efead3a6700 1 -- 172.21.15.153:6801/13188 --> 172.21.15.153:0/1272352374 -- osd_op_reply(46 foo [watch reconnect cookie 33829680 gen 1] v46'6 uv4 ondisk = 0) v8 -- ?+0 0xe938d80 con 0xd612380 ... 2018-10-30 15:03:18.453 7efea939e700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] notify_ack 33829680,184683593730 2018-10-30 15:03:18.453 7efea939e700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] acking notify on watch 33829680,client.4487 2018-10-30 15:03:18.453 7efea939e700 10 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] -- Watch(33829680,client.4487) notify_ack 2018-10-30 15:03:18.453 7efea939e700 15 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] log_op_stats osd_op(client.4487.0:48 10.1 10:9ea975d7:test-rados-api-smithi153-19840-9::foo:head [notify-ack cookie 0] snapc 0=[] ondisk+read+known_if_redirected e46) v8 inb 0 outb 0 lat 0.000482 2018-10-30 15:03:18.453 7efea939e700 20 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] publish_stats_to_osd reporting purged_snaps [] 2018-10-30 15:03:18.453 7efea939e700 15 osd.0 pg_epoch: 46 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] publish_stats_to_osd 46:43 2018-10-30 15:03:18.453 7efea939e700 1 -- 172.21.15.153:6801/13188 --> 172.21.15.153:0/1272352374 -- osd_op_reply(48 foo [notify-ack cookie 0] v0'0 uv4 ondisk = 0) v8 -- ?+0 0xe939400 con 0xd612380 ... 2018-10-30 15:03:19.241 7efeaf3aa700 10 Notify(34291712,197568495619 watchers=1) timeout 2018-10-30 15:03:19.241 7efeaf3aa700 10 Notify(34291712,197568495619 watchers=1) maybe_complete_notify -- 1 in progress watchers 2018-10-30 15:03:19.241 7efeaf3aa700 1 -- 172.21.15.153:6801/13188 --> 172.21.15.153:0/1272352374 -- watch-notify(notify_complete (2) cookie 34291712 notify 197568495619 ret -110) v3 -- ?+24 0xeb13c00 con 0xd612380 2018-10-30 15:03:19.241 7efeaf3aa700 10 osd.0 pg_epoch: 47 pg[10.1( v 46'6 (0'0,46'6] local-lis/les=44/45 n=2 ec=37/37 lis/c 44/44 les/c/f 45/45/0 44/44/37) [0,4,7] r=0 lpr=44 crt=43'5 lcod 43'5 mlcod 43'5 active+clean] -- Watch(33829680,client.4487) cancel_notify 197568495619 </pre>