Bug #9064
Updated by John Spray over 9 years ago
http://qa-proxy.ceph.com/teuthology/john-2014-08-10_02:14:59-rados-wip-mds-contexts-testing-basic-plana/411119/teuthology.log
<pre>
2014-08-10T13:16:56.604 INFO:tasks.rados.rados.0.plana54.stdout:3005: finishing write tid 1 to plana5416145-3005
2014-08-10T13:16:56.604 INFO:tasks.rados.rados.0.plana54.stderr:Error: finished tid 1 when last_acked_tid was 5
2014-08-10T13:16:56.604 INFO:tasks.rados.rados.0.plana54.stderr:./test/osd/RadosModel.h: In function 'virtual void WriteOp::_finish(TestOp::CallbackInfo*)' thread 7fde267fc700 time 2014-08-10 13:16:56.599123
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr:./test/osd/RadosModel.h: 828: FAILED assert(0)
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: ceph version 0.83-697-g7be5977 (7be59771bff09e2b46b5467627cbd7bb8b60727a)
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: 1: (WriteOp::_finish(TestOp::CallbackInfo*)+0x318) [0x419ff8]
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: 2: (write_callback(void*, void*)+0x21) [0x427991]
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: 3: (librados::C_AioSafe::finish(int)+0x1d) [0x7fde32afed7d]
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: 4: (Context::complete(int)+0x9) [0x7fde32adc229]
2014-08-10T13:16:56.605 INFO:tasks.rados.rados.0.plana54.stderr: 5: (Finisher::finisher_thread_entry()+0x1c0) [0x7fde32b99120]
2014-08-10T13:16:56.606 INFO:tasks.rados.rados.0.plana54.stderr: 6: (()+0x7e9a) [0x7fde3273fe9a]
2014-08-10T13:16:56.606 INFO:tasks.rados.rados.0.plana54.stderr: 7: (clone()+0x6d) [0x7fde31f563fd]
</pre>
Log messages for the object in question:
<pre>
2014-08-10T13:16:52.589 INFO:tasks.rados.rados.0.plana54.stdout:3005: write initial oid 3005
2014-08-10T13:16:52.589 INFO:tasks.rados.rados.0.plana54.stdout:3005: seq_num 3004 ranges {729974=423607,1867088=462886}
2014-08-10T13:16:52.621 INFO:tasks.rados.rados.0.plana54.stdout:3005: writing plana5416145-3005 from 729974 to 1153581 tid 1
2014-08-10T13:16:52.650 INFO:tasks.rados.rados.0.plana54.stdout:3005: writing plana5416145-3005 from 1867088 to 2329974 tid 2
2014-08-10T13:16:54.924 INFO:tasks.rados.rados.0.plana54.stdout:3005: finishing write tid 5 to plana5416145-3005
2014-08-10T13:16:56.604 INFO:tasks.rados.rados.0.plana54.stdout:3005: finishing write tid 1 to plana5416145-3005
</pre>
So that 5 is coming from... somewhere else. This seems less like an ordering issue and more that something is simply getting corrupted as we're seeing a tid complete that we never saw start for that object.