Ceph

ubuntu@teuthology:/a/teuthology-2014-08-24_02:30:02-rados-next-testing-basic-multi/446803

2014-08-24 14:13:30.039746 7faf01235700 20 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=113 (test-rados-api-plana40-12123-5 test-rados-api-plana40-121
23-6) owner=0 need_read_cap=0 need_write_cap=1 need_class_read_cap=0 need_class_write_cap=0 -> yes
2014-08-24 14:13:30.039776 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] handle_message: osd_op(client.4886.0:2 test-rados-api-plana40-12123-6/foo [watch add cooki
e 1 ver 0] 113.e3ef388a ondisk+read+write+known_if_redirected e941) v4
2014-08-24 14:13:30.039808 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] do_op osd_op(client.4886.0:2 test-rados-api-plana40-12123-6/foo [watch add cookie 1 ver 0]
 113.e3ef388a ondisk+read+write+known_if_redirected e941) v4 may_write -> write-ordered flags ondisk+read+write+known_if_redirected
2014-08-24 14:13:30.039844 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] readable_with_acting: locs:1(2),3(0)
2014-08-24 14:13:30.039879 7faf01235700  7 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] degraded e3ef388a/foo/head/test-rados-api-plana40-12123-6/113, recovering
2014-08-24 14:13:30.039906 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] prep_object_replica_pushes: on e3ef388a/foo/head/test-rados-api-plana40-12123-6/113
2014-08-24 14:13:30.039933 7faf01235700 15 filestore(/var/lib/ceph/osd/ceph-3) getattr 113.2s0_head/e3ef388a/foo/head/test-rados-api-plana40-12123-6/113/18446744073709551615/0 '_'
2014-08-24 14:13:30.040033 7faf01235700 10 filestore(/var/lib/ceph/osd/ceph-3) getattr 113.2s0_head/e3ef388a/foo/head/test-rados-api-plana40-12123-6/113/18446744073709551615/0 '_' = 624
2014-08-24 14:13:30.040064 7faf01235700 15 filestore(/var/lib/ceph/osd/ceph-3) getattr 113.2s0_head/e3ef388a/foo/head/test-rados-api-plana40-12123-6/113/18446744073709551615/0 'snapset'
2014-08-24 14:13:30.040084 7faf01235700 10 filestore(/var/lib/ceph/osd/ceph-3) getattr 113.2s0_head/e3ef388a/foo/head/test-rados-api-plana40-12123-6/113/18446744073709551615/0 'snapset' = 31
2014-08-24 14:13:30.040097 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] populate_obc_watchers e3ef388a/foo/head/test-rados-api-plana40-12123-6/113
2014-08-24 14:13:30.040127 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded]   unconnected watcher 1,client.4886 will expire 30.000000
2014-08-24 14:13:30.040157 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded]  -- Watch(1,client.4886) Watch()
2014-08-24 14:13:30.040174 7faf01235700 10 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded]  -- Watch(1,client.4886) disconnect
2014-08-24 14:13:30.040188 7faf01235700 15 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded]  -- Watch(1,client.4886) registering callback, timeout: 30
2014-08-24 14:13:30.040212 7faf01235700 20 osd.3 pg_epoch: 948 pg[113.2s0( v 944'2 (0'0,944'2] local-les=946 n=1 ec=941 les/c 946/944 945/945/941) [3,4,1] r=0 lpr=945 pi=941-944/1 crt=0'0 lcod 944'1 mlcod 0'0 active+degraded] ReplicatedPG::check_blacklisted_obc_watchers for obc e3ef388a/foo/head/test-rados-api-plan
...
and when the op comes around again, it's seen as a dup ...