Ceph

This is jewel v10.2.7 point release candidate

Run: http://pulpito.ceph.com/yuriw-2017-03-31_20:14:29-fs-jewel-distro-basic-smithi/
Log: http://qa-proxy.ceph.com/teuthology/yuriw-2017-03-31_20:14:29-fs-jewel-distro-basic-smithi/971350/teuthology.log

2017-04-01T02:07:46.706 INFO:tasks.ceph.osd.3.smithi050.stderr:os/filestore/FileStore.cc: In function 'void FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7fa7807c6700 time 2017-04-01 02:07:46.683701
2017-04-01T02:07:46.706 INFO:tasks.ceph.osd.3.smithi050.stderr:os/filestore/FileStore.cc: 2920: FAILED assert(0 == "unexpected error")
2017-04-01T02:07:46.723 INFO:tasks.ceph.osd.3.smithi050.stderr: ceph version 10.2.6-110-ga64d3e4 (a64d3e4b33e904aa6585464df8ffff6aafdec10c)
2017-04-01T02:07:46.723 INFO:tasks.ceph.osd.3.smithi050.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7fa78f86d6db]
2017-04-01T02:07:46.723 INFO:tasks.ceph.osd.3.smithi050.stderr: 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xefd) [0x7fa78f55fd4d]
2017-04-01T02:07:46.723 INFO:tasks.ceph.osd.3.smithi050.stderr: 3: (FileStore::_do_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, unsigned long, ThreadPool::TPHandle*)+0x3b) [0x7fa78f565a8b]
2017-04-01T02:07:46.723 INFO:tasks.ceph.osd.3.smithi050.stderr: 4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x2b5) [0x7fa78f565d75]
2017-04-01T02:07:46.724 INFO:tasks.ceph.osd.3.smithi050.stderr: 5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa6e) [0x7fa78f85eabe]
2017-04-01T02:07:46.724 INFO:tasks.ceph.osd.3.smithi050.stderr: 6: (ThreadPool::WorkThread::entry()+0x10) [0x7fa78f85f9a0]
2017-04-01T02:07:46.724 INFO:tasks.ceph.osd.3.smithi050.stderr: 7: (()+0x8184) [0x7fa78dd34184]
2017-04-01T02:07:46.724 INFO:tasks.ceph.osd.3.smithi050.stderr: 8: (clone()+0x6d) [0x7fa78be5f37d]
2017-04-01T02:07:46.724 INFO:tasks.ceph.osd.3.smithi050.stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

and in /a/yuriw-2017-03-31_20:14:29-fs-jewel-distro-basic-smithi/971350/remote/smithi050/log/ceph-osd.3.log.gz

3838317891-2017-04-01 02:07:46.689326 7fa766200700 20 osd.3 6 should_share_map osd.0 172.21.15.67:6801/32336 6
3838317991-2017-04-01 02:07:46.689335 7fa766200700 15 osd.3 6 enqueue_op 0x7fa79dae7f00 prio 196 cost 0 latency 0.000075 osd_repop_reply(client.4127.0:219466 2.7) v1
3838318146-2017-04-01 02:07:46.699069 7fa780fc7700 10 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:0955f7ff:::10000000181.0000000d:head# 110592~4096 = 4096
3838318300-2017-04-01 02:07:46.699090 7fa780fc7700 15 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:0955f7ff:::10000000181.0000000d:head# 1122304~4096
3838318448-2017-04-01 02:07:46.701911 7fa7807c6700 -1 os/filestore/FileStore.cc: In function 'void FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7fa7807c6700 time 2017-04-01 02:07:46.683701
3838318681-os/filestore/FileStore.cc: 2920: FAILED assert(0 == "unexpected error")
3838318753-
3838318754: ceph version 10.2.6-110-ga64d3e4 (a64d3e4b33e904aa6585464df8ffff6aafdec10c)
3838318831- 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7fa78f86d6db]
3838318928- 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xefd) [0x7fa78f55fd4d]
3838319054- 3: (FileStore::_do_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, unsigned long, ThreadPool::TPHandle*)+0x3b) [0x7fa78f565a8b]
3838319231- 4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x2b5) [0x7fa78f565d75]
3838319326- 5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa6e) [0x7fa78f85eabe]
3838319399- 6: (ThreadPool::WorkThread::entry()+0x10) [0x7fa78f85f9a0]
3838319459- 7: (()+0x8184) [0x7fa78dd34184]
3838319492- 8: (clone()+0x6d) [0x7fa78be5f37d]
3838319528- NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
3838319621-
3838319622---- begin dump of recent events ---
3838319658--10000> 2017-04-01 02:07:45.782228 7fa7807c6700 10 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:04d3465e:::10000000180.00000012:head# 2363392~4096 = 4096
3838319821- -9999> 2017-04-01 02:07:45.782230 7fa770618700  5 -- op tracker -- seq: 420717, time: 2017-04-01 02:07:45.782230, event: done, op: osd_repop_reply(client.4127.0:219312 2.0 ondisk, result = 0)
3838320014- -9998> 2017-04-01 02:07:45.782231 7fa7807c6700 15 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:04d3465e:::10000000180.00000012:head# 3325952~4096
3838320170- -9997> 2017-04-01 02:07:45.782241 7fa7807c6700 10 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:04d3465e:::10000000180.00000012:head# 3325952~4096 = 4096
3838320333- -9996> 2017-04-01 02:07:45.782233 7fa77d7c0700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28679 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] op_applied: 140369
3838320595- -9995> 2017-04-01 02:07:45.782252 7fa77d7c0700  5 -- op tracker -- seq: 420701, time: 2017-04-01 02:07:45.782252, event: op_applied, op: osd_op(client.4127.0:219324 2.42a452a0 1000000018b.00000000 [write 372736~4096,write 724992~4096,write 1245184~4096,write 1970176~4096,write 2551808~4096,write 2801664~4096,write 2916352~4096,write 2965504~4096,write 3198976~4096,write 3375104~4096,write 4018176~4096] snapc 1=[] ondisk+write+known_if_redirected e6)
3838321050- -9994> 2017-04-01 02:07:45.782268 7fa7807c6700 20 filestore(/var/lib/ceph/osd/ceph-3) fgetattrs 118 getting '_'
3838321163- -9993> 2017-04-01 02:07:45.782263 7fa77d7c0700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28679 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] op_applied version 6'28680
3838321433- -9992> 2017-04-01 02:07:45.782281 7fa7807c6700 20 filestore(/var/lib/ceph/osd/ceph-3) fgetattrs 118 getting 'snapset'
3838321552- -9991> 2017-04-01 02:07:45.782278 7fa77d7c0700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28680 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] op_applied: 140370
3838321814- -9990> 2017-04-01 02:07:45.782287 7fa77d7c0700  5 -- op tracker -- seq: 420704, time: 2017-04-01 02:07:45.782287, event: op_applied, op: osd_op(client.4127.0:219325 2.aecf4938 100000001b5.00000000 [write 1933312~4096,write 2576384~4096,write 3084288~4096] snapc 1=[] ondisk+write+known_if_redirected e6)
3838322119- -9989> 2017-04-01 02:07:45.782295 7fa7807c6700 15 filestore(/var/lib/ceph/osd/ceph-3) setattrs 2.0_head/#2:04d3465e:::10000000180.00000012:head#
3838322265- -9988> 2017-04-01 02:07:45.782294 7fa77d7c0700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28680 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] op_applied version 6'28681
3838322535- -9987> 2017-04-01 02:07:45.782307 7fa7817c8700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28681 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] op_commit: 140273
3838322796- -9986> 2017-04-01 02:07:45.782319 7fa7817c8700  5 -- op tracker -- seq: 420417, time: 2017-04-01 02:07:45.782318, event: op_commit, op: osd_op(client.4127.0:219140 2.6a3dd228 10000000190.00000006 [write 2048000~4096,write 2920448~4096,write 3018752~4096,write 4067328~4096] snapc 1=[] ondisk+write+known_if_redirected e6)
3838323119- -9985> 2017-04-01 02:07:45.782327 7fa7817c8700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28656 lua=6'28681 crt=6'28655 lcod 6'28655 mlcod 6'28655 active+clean] repop_all_committed: repop tid 140273 all committed 
3838323415- -9984> 2017-04-01 02:07:45.782338 7fa7817c8700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28657 lua=6'28681 crt=6'28655 lcod 6'28656 mlcod 6'28655 active+clean] eval_repop repgather(0x7fa79dc5e400 6'28657 rep_tid=140273 committed?=1 applied?=1) wants=d
3838323750- -9983> 2017-04-01 02:07:45.782347 7fa7817c8700 10 osd.3 pg_epoch: 6 pg[2.0( v 6'28682 (6'25667,6'28682] local-les=6 n=427 ec=5 les/c/f 6/6/0 5/5/5) [3,1] r=0 lpr=5 luod=6'28657 lua=6'28681 crt=6'28655 lcod 6'28656 mlcod 6'28655 active+clean]  commit: repgather(0x7fa79dc5e400 6'28657 rep_tid=140273 committed?=1 applied?=1)
3838324075- -9982> 2017-04-01 02:07:45.782354 7fa7807c6700 10 filestore(/var/lib/ceph/osd/ceph-3) setattrs 2.0_head/#2:04d3465e:::10000000180.00000012:head# = 0
--
3840817295-   -27> 2017-04-01 02:07:46.685248 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] do_osd_op  write 1941504~4096
3840817568-   -26> 2017-04-01 02:07:46.685258 7fa76f616700 20 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] make_writeable 2:f6624186:::100000001b4.00000013:head snapset=0x7fa79ae6a498  snapc=1=[]
3840817900-   -25> 2017-04-01 02:07:46.685270 7fa76f616700 20 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] make_writeable 2:f6624186:::100000001b4.00000013:head done, snapset=1=[]:[]+head
3840818224-   -24> 2017-04-01 02:07:46.685279 7fa76f616700 20 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] finish_ctx 2:f6624186:::100000001b4.00000013:head 0x7fa79c1b3800 op modify  
3840818544-   -23> 2017-04-01 02:07:46.685293 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean]  mtime unchanged at 0.000000
3840818816-   -22> 2017-04-01 02:07:46.685311 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean]  final snapset 1=[]:[]+head in 2:f6624186:::100000001b4.00000013:head
3840819129-   -21> 2017-04-01 02:07:46.685330 7fa76f616700 20 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean]  zeroing write result code 0
3840819401-   -20> 2017-04-01 02:07:46.685343 7fa76f616700 20 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean]  op order client.4127 tid 219466 last was 218685
3840819693-   -19> 2017-04-01 02:07:46.685355 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] new_repop rep_tid 140457 on osd_op(client.4127.0:219466 2.6182466f 100000001b4.00000013 [write 151552~4096,write 921600~4096,write 1941504~4096] snapc 1=[] ondisk+write+known_if_redirected e6) v7
3840820132-   -18> 2017-04-01 02:07:46.685375 7fa76f616700  7 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] issue_repop rep_tid 140457 o 2:f6624186:::100000001b4.00000013:head
3840820443-   -17> 2017-04-01 02:07:46.685405 7fa76f616700  5 -- op tracker -- seq: 420929, time: 2017-04-01 02:07:46.685405, event: waiting for subops from 0, op: osd_op(client.4127.0:219466 2.6182466f 100000001b4.00000013 [write 151552~4096,write 921600~4096,write 1941504~4096] snapc 1=[] ondisk+write+known_if_redirected e6)
3840820761-   -16> 2017-04-01 02:07:46.685442 7fa76f616700 20 osd.3 6 share_map_peer 0x7fa79ac98480 already has epoch 6
3840820870-   -15> 2017-04-01 02:07:46.685451 7fa76f616700  1 -- 172.21.15.50:6802/2903 --> 172.21.15.67:6801/32336 -- osd_repop(client.4127.0:219466 2.7 2:f6624186:::100000001b4.00000013:head v 6'29444) v1 -- ?+13059 0x7fa79d98b200 con 0x7fa79ac98480
3840821111-   -14> 2017-04-01 02:07:46.685479 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29443 (6'26420,6'29443] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] append_log log((6'26420,6'29443], crt=6'29427) [6'29444 (6'29347) modify   2:f6624186:::100000001b4.00000013:head by client.4127.0:219466 0.000000]
3840821502-   -13> 2017-04-01 02:07:46.685499 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29444 (6'26420,6'29444] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] add_log_entry 6'29444 (6'29347) modify   2:f6624186:::100000001b4.00000013:head by client.4127.0:219466 0.000000
3840821858-   -12> 2017-04-01 02:07:46.685512 7fa76f616700 10 osd.3 pg_epoch: 6 pg[2.7( v 6'29444 (6'26420,6'29444] local-les=6 n=441 ec=5 les/c/f 6/6/0 5/5/5) [3,0] r=0 lpr=5 luod=6'29428 lua=6'29437 crt=6'29427 lcod 6'29427 mlcod 6'29427 active+clean] append_log: trimming to 6'29427 entries 
3840822142-   -11> 2017-04-01 02:07:46.685535 7fa76f616700  5 write_log with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, dirty_divergent_priors: false, divergent_priors: 0, writeout_from: 6'29444, trimmed: 
3840822355-   -10> 2017-04-01 02:07:46.687830 7fa76f616700  5 filestore(/var/lib/ceph/osd/ceph-3) queue_transactions existing 0x7fa79aefadc0 osr(2.7 0x7fa79aa22760)
3840822509-    -9> 2017-04-01 02:07:46.687839 7fa76f616700 10 journal prepare_entry [Transaction(0x7fa79c910fc0)]
3840822612-    -8> 2017-04-01 02:07:46.687859 7fa76f616700 10 journal  len 14259 -> 16384 (head 40 pre_pad 0 bl 14259 post_pad 2045 tail 40) (bl alignment -1)
3840822760-    -7> 2017-04-01 02:07:46.689292 7fa766200700  1 -- 172.21.15.50:6802/2903 <== osd.0 172.21.15.67:6801/32336 105935 ==== osd_repop_reply(client.4127.0:219466 2.7) v1 ==== 83+0+0 (3727027206 0 0) 0x7fa79cd9cd00 con 0x7fa79ac98480
3840822991-    -6> 2017-04-01 02:07:46.689320 7fa766200700 10 osd.3 6 handle_replica_op osd_repop_reply(client.4127.0:219466 2.7) v1 epoch 6
3840823121-    -5> 2017-04-01 02:07:46.689326 7fa766200700 20 osd.3 6 should_share_map osd.0 172.21.15.67:6801/32336 6
3840823229-    -4> 2017-04-01 02:07:46.689335 7fa766200700 15 osd.3 6 enqueue_op 0x7fa79dae7f00 prio 196 cost 0 latency 0.000075 osd_repop_reply(client.4127.0:219466 2.7) v1
3840823392-    -3> 2017-04-01 02:07:46.689343 7fa766200700  5 -- op tracker -- seq: 420941, time: 2017-04-01 02:07:46.689342, event: queued_for_pg, op: osd_repop_reply(client.4127.0:219466 2.7)
3840823575-    -2> 2017-04-01 02:07:46.699069 7fa780fc7700 10 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:0955f7ff:::10000000181.0000000d:head# 110592~4096 = 4096
3840823737-    -1> 2017-04-01 02:07:46.699090 7fa780fc7700 15 filestore(/var/lib/ceph/osd/ceph-3) write 2.0_head/#2:0955f7ff:::10000000181.0000000d:head# 1122304~4096
3840823893-     0> 2017-04-01 02:07:46.701911 7fa7807c6700 -1 os/filestore/FileStore.cc: In function 'void FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7fa7807c6700 time 2017-04-01 02:07:46.683701