Ceph

   -89> 2014-03-14 12:46:01.500989 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] process_co
py_chunk 9b5006d4/plana1415210-41/head//3 tid 89 (0) Success
   -88> 2014-03-14 12:46:01.501050 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] process_co
py_chunk success; committing
   -87> 2014-03-14 12:46:01.501081 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] _write_cop
y_chunk 0x460edc0 1 attrs 3309889 bytes 0 keys
   -86> 2014-03-14 12:46:01.501132 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] process_co
py_chunk complete r = (0) Success
   -85> 2014-03-14 12:46:01.501168 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] execute_ct
x 0x2e1c080
   -84> 2014-03-14 12:46:01.501206 7f0e5cad0700  5 -- op tracker -- , seq: 6235, time: 2014-03-14 12:46:01.501206, event: started, request: osd_op(client.4126.0:3495 plana1415210-41 [copy-from ver 3589] 3.9b5006d4 snapc 1cb=[1cb,1c9,1c8] ack+ondisk+write e513) v4
   -83> 2014-03-14 12:46:01.501232 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] do_op 9b50
06d4/plana1415210-41/head//3 [copy-from ver 3589] ov 0'0 av 514'3615 snapc 1cb=[1cb,1c9,1c8] snapset 1ca=[1ca,1c9,1c8]:[1ca]
   -82> 2014-03-14 12:46:01.501272 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] do_osd_op 
9b5006d4/plana1415210-41/head//3 [copy-from ver 3589]
   -81> 2014-03-14 12:46:01.501303 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] do_osd_op 
 copy-from ver 3589
   -80> 2014-03-14 12:46:01.501334 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] finish_cop
yfrom on 9b5006d4/plana1415210-41/head//3
   -79> 2014-03-14 12:46:01.501369 7f0e5cad0700 15 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] do_osd_op_
effects on session 0x221f9a0
   -78> 2014-03-14 12:46:01.501401 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] make_write
able 9b5006d4/plana1415210-41/head//3 snapset=0x4882498  snapc=1cb=[1cb,1c9,1c8]
   -77> 2014-03-14 12:46:01.501433 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]]  setting D
IRTY flag
   -76> 2014-03-14 12:46:01.501466 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] make_write
able 9b5006d4/plana1415210-41/head//3 done, snapset=1cb=[1cb,1c9,1c8]:[1ca]+head
   -75> 2014-03-14 12:46:01.501499 7f0e5cad0700 20 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] finish_ctx
 9b5006d4/plana1415210-41/head//3 0x2e1c080 op modify  
   -74> 2014-03-14 12:46:01.501536 7f0e5cad0700 10 osd.1 pg_epoch: 514 pg[3.14( v 511'3614 (67'769,511'3614] local-les=514 n=69 ec=7 les/c 514/383 512/513/513) [0,2]/[1,2] r=-1 lpr=513 pi=378-512/2 rops=5 bft=(0,255) crt=84'1054 lcod 509'3611 mlcod 0'0 active+remapped+backfilling snaptrimq=[1ca~1,1cc~1]] get_object
     0> 2014-03-14 12:46:01.505370 7f0e5cad0700 -1 osd/ReplicatedPG.cc: In function 'void ReplicatedPG::finish_ctx(ReplicatedPG::OpContext*, int)' thread 7f0e5cad0700 time 2014-03-14 12:46:01.501580
osd/ReplicatedPG.cc: 4991: FAILED assert(got)

 ceph version 0.77-869-g87c911c (87c911cede50ffadcbb5cfd553df8d436a9975d1)
 1: (ReplicatedPG::finish_ctx(ReplicatedPG::OpContext*, int)+0x2aa8) [0x8964b8]
 2: (ReplicatedPG::prepare_transaction(ReplicatedPG::OpContext*)+0xc8) [0x8ab128]
 3: (ReplicatedPG::execute_ctx(ReplicatedPG::OpContext*)+0xb0f) [0x8abeff]
 4: (CopyFromCallback::finish(boost::tuples::tuple<int, ReplicatedPG::CopyResults*, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type>)+0x4a) [0x8f079a]
 5: (GenContext<boost::tuples::tuple<int, ReplicatedPG::CopyResults*, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type> >::complete(boost::tuples::tuple<int, ReplicatedPG::CopyResults*, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type>)+0x15) [0x8c7e25]
 6: (ReplicatedPG::process_copy_chunk(hobject_t, unsigned long, int)+0xb5d) [0x89145d]
 7: (C_Copyfrom::finish(int)+0xa7) [0x8ef3d7]
 8: (Context::complete(int)+0x9) [0x66d9d9]
 9: (Finisher::finisher_thread_entry()+0x1c0) [0x9a2a10]
 10: (()+0x7e9a) [0x7f0e752fbe9a]

ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2014-03-14_09:31:46-rados:thrash-wip-7709-testing-basic-plana/130315