|
Hi, I have a small cluster(5 nodes, 20OSDs), where an OSD crashed. There is no any other signal of problems. No kernel message, so the disks seem to be OK. I tried to restart the OSD but the process stops almost immediately with the same logs. Version is 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) on an ubuntu 14.04 with kernel 3.13.0-68-generic. See the logs from the relevant OSD below. How can I fix this or what other info needed to find the issue? Thanks, Csaba 2015-12-02 12:24:02.897795 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1cd deep-scrub starts 2015-12-02 12:24:55.524671 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1cd deep-scrub ok 2015-12-02 13:12:03.726819 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1d1 deep-scrub starts 2015-12-02 13:12:54.071754 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1d1 deep-scrub ok 2015-12-02 14:00:03.679075 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1d5 deep-scrub starts 2015-12-02 14:01:01.918174 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.1d5 deep-scrub ok 2015-12-02 14:02:00.766516 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.15d scrub starts 2015-12-02 14:02:03.769314 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 1.15d scrub ok 2015-12-02 14:14:39.957244 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.1e5 scrub starts 2015-12-02 14:14:39.980339 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.1e5 scrub ok 2015-12-02 15:39:49.182272 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.93 scrub starts 2015-12-02 15:39:49.475440 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.93 scrub ok 2015-12-02 15:39:50.183518 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.124 scrub starts 2015-12-02 15:39:50.460812 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.124 scrub ok 2015-12-02 15:39:52.184466 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.15d scrub starts 2015-12-02 15:39:52.209681 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.15d scrub ok 2015-12-02 15:39:59.187012 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.184 scrub starts 2015-12-02 15:39:59.216332 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.184 scrub ok 2015-12-02 15:40:01.188834 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.4 scrub starts 2015-12-02 15:40:01.225628 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.4 scrub ok 2015-12-02 16:54:17.266052 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.96 scrub starts 2015-12-02 16:54:17.286040 7f1dcd6d5700 0 log_channel(cluster) log [INF] : 0.96 scrub ok 2015-12-02 17:08:33.788969 7f1de2a92700 0 filestore(/var/lib/ceph/osd/ceph-7) error (1) Operation not permitted not handled on operation 0x15778000 (35890348.0.0, or op 0, counting from 0) 2015-12-02 17:08:33.788977 7f1de2a92700 0 filestore(/var/lib/ceph/osd/ceph-7) unexpected error code 2015-12-02 17:08:33.788978 7f1de2a92700 0 filestore(/var/lib/ceph/osd/ceph-7) transaction dump: { "ops": [ { "op_num": 0, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "0000004386.00000000000001801497": 176 } }, { "op_num": 1, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "_epoch": 4, "_info": 745 } }, { "op_num": 2, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "0000004386.00000000000001801497": 176, "can_rollback_to": 12, "rollback_info_trimmed_to": 12 } }, { "op_num": 3, "op_name": "op_setallochint", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "expected_object_size": "4194304", "expected_write_size": "4194304" }, { "op_num": 4, "op_name": "write", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "length": 4096, "offset": 274432, "bufferlist length": 4096 }, { "op_num": 5, "op_name": "setattr", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "name": "_", "length": 267 }, { "op_num": 6, "op_name": "setattr", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "name": "snapset", "length": 31 } ] } 2015-12-02 17:08:33.793090 7f1de2a92700 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7f1de2a92700 time 2015-12-02 17:08:33.790987 os/FileStore.cc: 2757: FAILED assert(0 == "unexpected error") ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0xbc60eb] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x16a) [0x92a52a] 5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa5e) [0xbb6b4e] 6: (ThreadPool::WorkThread::entry()+0x10) [0xbb7bf0] 7: (()+0x8182) [0x7f1df05dc182] 8: (clone()+0x6d) [0x7f1deeb4747d] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. --- begin dump of recent events --- -10000> 2015-12-02 17:07:16.133917 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6803/30958 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x118f8400 con 0x11410c00 -9999> 2015-12-02 17:07:16.133947 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6806/31415 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x8ea6c00 con 0x11411180 -9998> 2015-12-02 17:07:16.133983 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6807/31415 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x8ea4a00 con 0x11411020 -9997> 2015-12-02 17:07:16.134008 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6810/31820 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x1402ba00 con 0x1151e260 -9996> 2015-12-02 17:07:16.134030 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6811/31820 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x141a1600 con 0x1151e100 -9995> 2015-12-02 17:07:16.134052 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6814/32269 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x15ccfa00 con 0x11411860 -9994> 2015-12-02 17:07:16.134071 7f1dcc6d3700 1 -- 192.168.239.12:0/5845 --> 192.168.239.15:6815/32269 -- osd_ping(ping e4386 stamp 2015-12-02 17:07:16.133090) v2 -- ?+0 0x12b53000 con 0x11411700 -9993> 2015-12-02 17:07:16.134285 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.3 192.168.239.11:6814/28410 136564 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x15b36400 con 0x131ee100 -9992> 2015-12-02 17:07:16.134329 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.17 192.168.239.15:6806/31415 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x5a65e00 con 0x11411180 -9991> 2015-12-02 17:07:16.134352 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.15 192.168.239.14:6807/11443 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xbc59400 con 0x1151c6e0 -9990> 2015-12-02 17:07:16.134372 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.14 192.168.239.14:6814/10898 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x14067000 con 0x1151c000 -9989> 2015-12-02 17:07:16.134391 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.14 192.168.239.14:6815/10898 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x12f46000 con 0x1151d760 -9988> 2015-12-02 17:07:16.134409 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.18 192.168.239.15:6811/31820 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x8e5e600 con 0x1151e100 -9987> 2015-12-02 17:07:16.134428 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.10 192.168.239.14:6803/10083 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x7bd4e00 con 0x1151de40 -9986> 2015-12-02 17:07:16.134447 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.0 192.168.239.11:6805/24315 136702 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x13914800 con 0x11e9d020 -9985> 2015-12-02 17:07:16.134570 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.18 192.168.239.15:6810/31820 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x1a2d3000 con 0x1151e260 -9984> 2015-12-02 17:07:16.134806 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.0 192.168.239.11:6806/24315 136702 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x12324e00 con 0x12bb2520 -9983> 2015-12-02 17:07:16.134844 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.6 192.168.239.13:6814/28061 136498 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x1539b800 con 0x132e5600 -9982> 2015-12-02 17:07:16.135003 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.13 192.168.239.14:6811/10470 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x9b84000 con 0x1151d4a0 -9981> 2015-12-02 17:07:16.135035 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.10 192.168.239.14:6802/10083 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xa222e00 con 0x1151dfa0 -9980> 2015-12-02 17:07:16.135052 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.1 192.168.239.11:6815/25934 136683 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x14940e00 con 0x1151db80 -9979> 2015-12-02 17:07:16.135085 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.6 192.168.239.13:6815/28061 136498 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x19eda800 con 0x13067180 -9978> 2015-12-02 17:07:16.135139 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.8 192.168.239.13:6804/30030 136475 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x15e26a00 con 0x12620aa0 -9977> 2015-12-02 17:07:16.135256 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.9 192.168.239.13:6808/30795 136451 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x15a87000 con 0x12620c00 -9976> 2015-12-02 17:07:16.135307 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.9 192.168.239.13:6810/30795 136451 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x136f6a00 con 0x12620d60 -9975> 2015-12-02 17:07:16.135353 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.11 192.168.239.13:6809/32093 136390 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x137e4600 con 0x13387760 -9974> 2015-12-02 17:07:16.135380 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.11 192.168.239.13:6811/32093 136390 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xd57ae00 con 0x13387600 -9973> 2015-12-02 17:07:16.135404 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.16 192.168.239.15:6802/30958 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x135ae400 con 0x11410680 -9972> 2015-12-02 17:07:16.135427 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.16 192.168.239.15:6803/30958 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x12745000 con 0x11410c00 -9971> 2015-12-02 17:07:16.135450 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.17 192.168.239.15:6807/31415 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xc32f400 con 0x11411020 -9970> 2015-12-02 17:07:16.135473 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.19 192.168.239.15:6814/32269 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xf6ede00 con 0x11411860 -9969> 2015-12-02 17:07:16.135496 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.19 192.168.239.15:6815/32269 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x140f7c00 con 0x11411700 -9968> 2015-12-02 17:07:16.135518 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.15 192.168.239.14:6806/11443 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x15c45400 con 0x114112e0 -9967> 2015-12-02 17:07:16.135541 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.13 192.168.239.14:6810/10470 136991 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x12b58000 con 0x1151d600 -9966> 2015-12-02 17:07:16.135566 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.1 192.168.239.11:6812/25934 136683 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x118f6000 con 0x1151dce0 -9965> 2015-12-02 17:07:16.135589 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.2 192.168.239.11:6811/26553 136650 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0xfb16000 con 0xf5d55a0 -9964> 2015-12-02 17:07:16.135612 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.2 192.168.239.11:6813/26553 136650 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x13479000 con 0xf5d22c0 -9963> 2015-12-02 17:07:16.135634 7f1dd9eee700 1 -- 192.168.239.12:0/5845 <== osd.3 192.168.239.11:6807/28410 136564 ==== osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.133090) v2 ==== 47+0+0 (20801387 0 0) 0x120d5200 con 0x131edfa0 -9962> 2015-12-02 17:07:16.357232 7f1dd8eec700 1 -- 192.168.239.12:6803/5845 <== osd.16 192.168.239.15:0/30958 136985 ==== osd_ping(ping e4386 stamp 2015-12-02 17:07:16.358775) v2 ==== 47+0+0 (3878973734 0 0) 0x1577a400 con 0x11b1c680 -9961> 2015-12-02 17:07:16.357253 7f1dd8eec700 1 -- 192.168.239.12:6803/5845 --> 192.168.239.15:0/30958 -- osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.358775) v2 -- ?+0 0x121f4200 con 0x11b1c680 -9960> 2015-12-02 17:07:16.357801 7f1dd76e9700 1 -- 192.168.239.12:6802/5845 <== osd.16 192.168.239.15:0/30958 136985 ==== osd_ping(ping e4386 stamp 2015-12-02 17:07:16.358775) v2 ==== 47+0+0 (3878973734 0 0) 0x133d4a00 con 0x11b1cd60 -9959> 2015-12-02 17:07:16.357814 7f1dd76e9700 1 -- 192.168.239.12:6802/5845 --> 192.168.239.15:0/30958 -- osd_ping(ping_reply e4386 stamp 2015-12-02 17:07:16.358775) v2 -- ?+0 0x12b4d800 con 0x11b1cd60 -9958> 2015-12-02 17:07:16.457591 7f1de6ead700 5 osd.7 4386 tick ... -37> 2015-12-02 17:08:33.790279 7f1dc2d81700 1 -- 192.168.239.12:6801/5845 <== osd.0 192.168.239.11:6801/24315 337983 ==== osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) v1 ==== 913+0+8955 (813233606 0 142017132) 0x3edca00 con 0x15c2ed60 -36> 2015-12-02 17:08:33.790292 7f1dc2d81700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790099, event: header_read, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -35> 2015-12-02 17:08:33.790298 7f1dc2d81700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790099, event: throttled, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -34> 2015-12-02 17:08:33.790301 7f1dc2d81700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790276, event: all_read, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -33> 2015-12-02 17:08:33.790304 7f1dc2d81700 5 -- op tracker -- seq: 5567240, time: 0.000000, event: dispatched, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -32> 2015-12-02 17:08:33.790321 7f1dd06db700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790321, event: reached_pg, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -31> 2015-12-02 17:08:33.790348 7f1dd06db700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790348, event: started, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -30> 2015-12-02 17:08:33.790382 7f1dd06db700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790382, event: started, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -29> 2015-12-02 17:08:33.790429 7f1dd06db700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790429, event: commit_queued_for_journal_write, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -28> 2015-12-02 17:08:33.790457 7f1de4a96700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790457, event: write_thread_in_journal_buffer, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -27> 2015-12-02 17:08:33.790602 7f1de4295700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790602, event: journaled_completion_queued, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -26> 2015-12-02 17:08:33.790669 7f1de1a90700 5 -- op tracker -- seq: 5567240, time: 2015-12-02 17:08:33.790669, event: commit_sent, op: osd_repop(client.617405.0:1240585 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801499) -25> 2015-12-02 17:08:33.790678 7f1de1a90700 1 -- 192.168.239.12:6801/5845 --> 192.168.239.11:6801/24315 -- osd_repop_reply(client.617405.0:1240585 1.136 ondisk, result = 0) v1 -- ?+0 0x11ee0240 con 0x15c2ed60 -24> 2015-12-02 17:08:33.788978 7f1de2a92700 0 filestore(/var/lib/ceph/osd/ceph-7) transaction dump: { "ops": [ { "op_num": 0, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "0000004386.00000000000001801497": 176 } }, { "op_num": 1, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "_epoch": 4, "_info": 745 } }, { "op_num": 2, "op_name": "omap_setkeys", "collection": "1.136_head", "oid": "136\/\/head\/\/1", "attr_lens": { "0000004386.00000000000001801497": 176, "can_rollback_to": 12, "rollback_info_trimmed_to": 12 } }, { "op_num": 3, "op_name": "op_setallochint", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "expected_object_size": "4194304", "expected_write_size": "4194304" }, { "op_num": 4, "op_name": "write", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "length": 4096, "offset": 274432, "bufferlist length": 4096 }, { "op_num": 5, "op_name": "setattr", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "name": "_", "length": 267 }, { "op_num": 6, "op_name": "setattr", "collection": "1.136_head", "oid": "9afc9936\/rb.0.2f6a4.238e1f29.000000001a74\/head\/\/1", "name": "snapset", "length": 31 } ] } -23> 2015-12-02 17:08:33.792015 7f1dc2d81700 1 -- 192.168.239.12:6801/5845 <== osd.0 192.168.239.11:6801/24315 337984 ==== osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) v1 ==== 913+0+8955 (2008231596 0 2894498157) 0x4b2c000 con 0x15c2ed60 -22> 2015-12-02 17:08:33.792028 7f1dc2d81700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.791979, event: header_read, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -21> 2015-12-02 17:08:33.792033 7f1dc2d81700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.791980, event: throttled, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -20> 2015-12-02 17:08:33.792037 7f1dc2d81700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792012, event: all_read, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -19> 2015-12-02 17:08:33.792039 7f1dc2d81700 5 -- op tracker -- seq: 5567241, time: 0.000000, event: dispatched, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -18> 2015-12-02 17:08:33.792056 7f1dd2ee0700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792056, event: reached_pg, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -17> 2015-12-02 17:08:33.792066 7f1dd2ee0700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792066, event: started, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -16> 2015-12-02 17:08:33.792102 7f1dd2ee0700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792101, event: started, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -15> 2015-12-02 17:08:33.792115 7f1dd2ee0700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792115, event: commit_queued_for_journal_write, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -14> 2015-12-02 17:08:33.792136 7f1de4a96700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792136, event: write_thread_in_journal_buffer, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -13> 2015-12-02 17:08:33.792362 7f1de4295700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792362, event: journaled_completion_queued, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -12> 2015-12-02 17:08:33.792374 7f1de1a90700 5 -- op tracker -- seq: 5567241, time: 2015-12-02 17:08:33.792374, event: commit_sent, op: osd_repop(client.617405.0:1240586 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801500) -11> 2015-12-02 17:08:33.792380 7f1de1a90700 1 -- 192.168.239.12:6801/5845 --> 192.168.239.11:6801/24315 -- osd_repop_reply(client.617405.0:1240586 1.136 ondisk, result = 0) v1 -- ?+0 0x11ee0fc0 con 0x15c2ed60 -10> 2015-12-02 17:08:33.792857 7f1dc2d81700 1 -- 192.168.239.12:6801/5845 <== osd.0 192.168.239.11:6801/24315 337985 ==== osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) v1 ==== 913+0+4859 (3523223829 0 1517543299) 0xc9c5600 con 0x15c2ed60 -9> 2015-12-02 17:08:33.792868 7f1dc2d81700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792821, event: header_read, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -8> 2015-12-02 17:08:33.792872 7f1dc2d81700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792822, event: throttled, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -7> 2015-12-02 17:08:33.792876 7f1dc2d81700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792854, event: all_read, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -6> 2015-12-02 17:08:33.792879 7f1dc2d81700 5 -- op tracker -- seq: 5567242, time: 0.000000, event: dispatched, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -5> 2015-12-02 17:08:33.792896 7f1dd06db700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792896, event: reached_pg, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -4> 2015-12-02 17:08:33.792904 7f1dd06db700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792904, event: started, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -3> 2015-12-02 17:08:33.792940 7f1dd06db700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.792940, event: started, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -2> 2015-12-02 17:08:33.793001 7f1dd06db700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.793001, event: commit_queued_for_journal_write, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) -1> 2015-12-02 17:08:33.793029 7f1de4a96700 5 -- op tracker -- seq: 5567242, time: 2015-12-02 17:08:33.793029, event: write_thread_in_journal_buffer, op: osd_repop(client.617405.0:1240587 1.136 9afc9936/rb.0.2f6a4.238e1f29.000000001a74/head//1 v 4386'1801501) 0> 2015-12-02 17:08:33.793090 7f1de2a92700 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7f1de2a92700 time 2015-12-02 17:08:33.790987 os/FileStore.cc: 2757: FAILED assert(0 == "unexpected error") ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0xbc60eb] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x16a) [0x92a52a] 5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa5e) [0xbb6b4e] 6: (ThreadPool::WorkThread::entry()+0x10) [0xbb7bf0] 7: (()+0x8182) [0x7f1df05dc182] 8: (clone()+0x6d) [0x7f1deeb4747d] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. --- logging levels --- 0/ 5 none 0/ 1 lockdep 0/ 1 context 1/ 1 crush 1/ 5 mds 1/ 5 mds_balancer 1/ 5 mds_locker 1/ 5 mds_log 1/ 5 mds_log_expire 1/ 5 mds_migrator 0/ 1 buffer 0/ 1 timer 0/ 1 filer 0/ 1 striper 0/ 1 objecter 0/ 5 rados 0/ 5 rbd 0/ 5 rbd_replay 0/ 5 journaler 0/ 5 objectcacher 0/ 5 client 0/ 5 osd 0/ 5 optracker 0/ 5 objclass 1/ 3 filestore 1/ 3 keyvaluestore 1/ 3 journal 0/ 5 ms 1/ 5 mon 0/10 monc 1/ 5 paxos 0/ 5 tp 1/ 5 auth 1/ 5 crypto 1/ 1 finisher 1/ 5 heartbeatmap 1/ 5 perfcounter 1/ 5 rgw 1/10 civetweb 1/ 5 javaclient 1/ 5 asok 1/ 1 throttle 0/ 0 refs 1/ 5 xio -2/-2 (syslog threshold) -1/-1 (stderr threshold) max_recent 10000 max_new 1000 log_file /var/log/ceph/ceph-osd.7.log --- end dump of recent events --- 2015-12-02 17:08:33.836926 7f1de2a92700 -1 *** Caught signal (Aborted) ** in thread 7f1de2a92700 ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: /usr/bin/ceph-osd() [0xacd7ba] 2: (()+0x10340) [0x7f1df05e4340] 3: (gsignal()+0x39) [0x7f1deea83cc9] 4: (abort()+0x148) [0x7f1deea870d8] 5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7f1def38e535] 6: (()+0x5e6d6) [0x7f1def38c6d6] 7: (()+0x5e703) [0x7f1def38c703] 8: (()+0x5e922) [0x7f1def38c922] 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x278) [0xbc62d8] 10: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 11: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 12: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x16a) [0x92a52a] 13: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa5e) [0xbb6b4e] 14: (ThreadPool::WorkThread::entry()+0x10) [0xbb7bf0] 15: (()+0x8182) [0x7f1df05dc182] 16: (clone()+0x6d) [0x7f1deeb4747d] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. ... -26> 2015-12-02 17:08:33.807067 7f1dc267a700 1 -- 192.168.239.12:6801/5845 <== osd.2 192.168.239.11:6810/26553 502584 ==== osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) v1 ==== 913+0+8954 (3282119646 0 1051279161) 0x19f79200 con 0x129ba680 -25> 2015-12-02 17:08:33.807076 7f1dc267a700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807039, event: header_read, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -24> 2015-12-02 17:08:33.807078 7f1dc267a700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807039, event: throttled, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -23> 2015-12-02 17:08:33.807080 7f1dc267a700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807064, event: all_read, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -22> 2015-12-02 17:08:33.807082 7f1dc267a700 5 -- op tracker -- seq: 5567255, time: 0.000000, event: dispatched, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -21> 2015-12-02 17:08:33.807096 7f1dcfeda700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807096, event: reached_pg, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -20> 2015-12-02 17:08:33.807102 7f1dcfeda700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807102, event: started, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -19> 2015-12-02 17:08:33.807388 7f1dc267a700 1 -- 192.168.239.12:6801/5845 <== osd.2 192.168.239.11:6810/26553 502585 ==== osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) v1 ==== 913+0+4858 (543721316 0 446914438) 0x1569fe00 con 0x129ba680 -18> 2015-12-02 17:08:33.807397 7f1dc267a700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807360, event: header_read, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -17> 2015-12-02 17:08:33.807359 7f1dcfeda700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807359, event: started, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -16> 2015-12-02 17:08:33.807400 7f1dc267a700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807361, event: throttled, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -15> 2015-12-02 17:08:33.807402 7f1dc267a700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807384, event: all_read, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -14> 2015-12-02 17:08:33.807404 7f1dc267a700 5 -- op tracker -- seq: 5567256, time: 0.000000, event: dispatched, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -13> 2015-12-02 17:08:33.807409 7f1dcfeda700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807409, event: commit_queued_for_journal_write, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -12> 2015-12-02 17:08:33.807543 7f1de4a96700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807543, event: write_thread_in_journal_buffer, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -11> 2015-12-02 17:08:33.807548 7f1dd26df700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807548, event: reached_pg, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -10> 2015-12-02 17:08:33.807555 7f1dd26df700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807555, event: started, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -9> 2015-12-02 17:08:33.807619 7f1de4295700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807619, event: journaled_completion_queued, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -8> 2015-12-02 17:08:33.807716 7f1dd26df700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807716, event: started, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -7> 2015-12-02 17:08:33.807727 7f1dd26df700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807727, event: commit_queued_for_journal_write, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -6> 2015-12-02 17:08:33.807739 7f1de1a90700 5 -- op tracker -- seq: 5567255, time: 2015-12-02 17:08:33.807739, event: commit_sent, op: osd_repop(client.617405.0:1240640 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778364) -5> 2015-12-02 17:08:33.807743 7f1de4a96700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807743, event: write_thread_in_journal_buffer, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -4> 2015-12-02 17:08:33.807743 7f1de1a90700 1 -- 192.168.239.12:6801/5845 --> 192.168.239.11:6810/26553 -- osd_repop_reply(client.617405.0:1240640 1.ba ondisk, result = 0) v1 -- ?+0 0x13c24640 con 0x129ba680 -3> 2015-12-02 17:08:33.807822 7f1de4295700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807822, event: journaled_completion_queued, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -2> 2015-12-02 17:08:33.807827 7f1de1a90700 5 -- op tracker -- seq: 5567256, time: 2015-12-02 17:08:33.807827, event: commit_sent, op: osd_repop(client.617405.0:1240641 1.ba 4640e0ba/rb.0.2f6a4.238e1f29.000000001a81/head//1 v 4386'778365) -1> 2015-12-02 17:08:33.808033 7f1de1a90700 1 -- 192.168.239.12:6801/5845 --> 192.168.239.11:6810/26553 -- osd_repop_reply(client.617405.0:1240641 1.ba ondisk, result = 0) v1 -- ?+0 0x13c23d40 con 0x129ba680 0> 2015-12-02 17:08:33.836926 7f1de2a92700 -1 *** Caught signal (Aborted) ** in thread 7f1de2a92700 ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: /usr/bin/ceph-osd() [0xacd7ba] 2: (()+0x10340) [0x7f1df05e4340] 3: (gsignal()+0x39) [0x7f1deea83cc9] 4: (abort()+0x148) [0x7f1deea870d8] 5: (__gnu_cxx::__verbose_terminate_handler()+0x155) [0x7f1def38e535] 6: (()+0x5e6d6) [0x7f1def38c6d6] 7: (()+0x5e703) [0x7f1def38c703] 8: (()+0x5e922) [0x7f1def38c922] 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x278) [0xbc62d8] 10: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 11: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 12: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x16a) [0x92a52a] 13: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa5e) [0xbb6b4e] 14: (ThreadPool::WorkThread::entry()+0x10) [0xbb7bf0] 15: (()+0x8182) [0x7f1df05dc182] 16: (clone()+0x6d) [0x7f1deeb4747d] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. 2015-12-02 17:09:38.407478 7f9d9cd87900 0 ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43), process ceph-osd, pid 5415 2015-12-02 17:09:38.425040 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) backend xfs (magic 0x58465342) 2015-12-02 17:09:38.427504 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: FIEMAP ioctl is supported and appears to work 2015-12-02 17:09:38.427519 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option 2015-12-02 17:09:38.491583 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: syncfs(2) syscall fully supported (by glibc and kernel) 2015-12-02 17:09:38.491815 7f9d9cd87900 0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_feature: extsize is supported and kernel 3.13.0-68-generic >= 3.5 2015-12-02 17:09:38.631694 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled 2015-12-02 17:09:39.303520 7f9d9cd87900 1 journal _open /var/lib/ceph/osd/ceph-7/journal fd 19: 10737418240 bytes, block size 4096 bytes, directio = 1, aio = 1 2015-12-02 17:09:39.305243 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) error (1) Operation not permitted not handled on operation 0x4f9b665 (35890294.0.0, or op 0, counting from 0) 2015-12-02 17:09:39.305260 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) unexpected error code 2015-12-02 17:09:39.305261 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) transaction dump: { "ops": [ { "op_num": 0, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "0000004386.00000000000000976285": 176 } }, { "op_num": 1, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "_epoch": 4, "_info": 745 } }, { "op_num": 2, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "0000004386.00000000000000976285": 176, "can_rollback_to": 12, "rollback_info_trimmed_to": 12 } }, { "op_num": 3, "op_name": "op_setallochint", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "expected_object_size": "4194304", "expected_write_size": "4194304" }, { "op_num": 4, "op_name": "write", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "length": 4096, "offset": 294912, "bufferlist length": 4096 }, { "op_num": 5, "op_name": "setattr", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "name": "_", "length": 267 }, { "op_num": 6, "op_name": "setattr", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "name": "snapset", "length": 31 } ] } 2015-12-02 17:09:39.309384 7f9d9cd87900 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7f9d9cd87900 time 2015-12-02 17:09:39.305384 os/FileStore.cc: 2757: FAILED assert(0 == "unexpected error") ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0xbc60eb] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 4: (JournalingObjectStore::journal_replay(unsigned long)+0x5cb) [0x94355b] 5: (FileStore::mount()+0x3bb6) [0x9139f6] 6: (OSD::init()+0x259) [0x6c59b9] 7: (main()+0x2860) [0x6527e0] 8: (__libc_start_main()+0xf5) [0x7f9d99ec7ec5] 9: /usr/bin/ceph-osd() [0x66b887] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. --- begin dump of recent events --- -56> 2015-12-02 17:09:38.405558 7f9d9cd87900 5 asok(0x4dc0000) register_command perfcounters_dump hook 0x4d60050 -55> 2015-12-02 17:09:38.405593 7f9d9cd87900 5 asok(0x4dc0000) register_command 1 hook 0x4d60050 -54> 2015-12-02 17:09:38.405597 7f9d9cd87900 5 asok(0x4dc0000) register_command perf dump hook 0x4d60050 -53> 2015-12-02 17:09:38.405604 7f9d9cd87900 5 asok(0x4dc0000) register_command perfcounters_schema hook 0x4d60050 -52> 2015-12-02 17:09:38.405610 7f9d9cd87900 5 asok(0x4dc0000) register_command 2 hook 0x4d60050 -51> 2015-12-02 17:09:38.405612 7f9d9cd87900 5 asok(0x4dc0000) register_command perf schema hook 0x4d60050 -50> 2015-12-02 17:09:38.405617 7f9d9cd87900 5 asok(0x4dc0000) register_command perf reset hook 0x4d60050 -49> 2015-12-02 17:09:38.405620 7f9d9cd87900 5 asok(0x4dc0000) register_command config show hook 0x4d60050 -48> 2015-12-02 17:09:38.405626 7f9d9cd87900 5 asok(0x4dc0000) register_command config set hook 0x4d60050 -47> 2015-12-02 17:09:38.405629 7f9d9cd87900 5 asok(0x4dc0000) register_command config get hook 0x4d60050 -46> 2015-12-02 17:09:38.405633 7f9d9cd87900 5 asok(0x4dc0000) register_command config diff hook 0x4d60050 -45> 2015-12-02 17:09:38.405636 7f9d9cd87900 5 asok(0x4dc0000) register_command log flush hook 0x4d60050 -44> 2015-12-02 17:09:38.405638 7f9d9cd87900 5 asok(0x4dc0000) register_command log dump hook 0x4d60050 -43> 2015-12-02 17:09:38.405641 7f9d9cd87900 5 asok(0x4dc0000) register_command log reopen hook 0x4d60050 -42> 2015-12-02 17:09:38.407478 7f9d9cd87900 0 ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43), process ceph-osd, pid 5415 -41> 2015-12-02 17:09:38.410389 7f9d9cd87900 1 -- 192.168.239.12:0/0 learned my addr 192.168.239.12:0/0 -40> 2015-12-02 17:09:38.410416 7f9d9cd87900 1 accepter.accepter.bind my_inst.addr is 192.168.239.12:6800/5415 need_addr=0 -39> 2015-12-02 17:09:38.410444 7f9d9cd87900 1 -- 192.168.239.12:0/0 learned my addr 192.168.239.12:0/0 -38> 2015-12-02 17:09:38.410451 7f9d9cd87900 1 accepter.accepter.bind my_inst.addr is 192.168.239.12:6801/5415 need_addr=0 -37> 2015-12-02 17:09:38.410474 7f9d9cd87900 1 -- 192.168.239.12:0/0 learned my addr 192.168.239.12:0/0 -36> 2015-12-02 17:09:38.410486 7f9d9cd87900 1 accepter.accepter.bind my_inst.addr is 192.168.239.12:6802/5415 need_addr=0 -35> 2015-12-02 17:09:38.410504 7f9d9cd87900 1 -- 192.168.239.12:0/0 learned my addr 192.168.239.12:0/0 -34> 2015-12-02 17:09:38.410515 7f9d9cd87900 1 accepter.accepter.bind my_inst.addr is 192.168.239.12:6803/5415 need_addr=0 -33> 2015-12-02 17:09:38.414129 7f9d9cd87900 5 asok(0x4dc0000) init /var/run/ceph/ceph-osd.7.asok -32> 2015-12-02 17:09:38.414161 7f9d9cd87900 5 asok(0x4dc0000) bind_and_listen /var/run/ceph/ceph-osd.7.asok -31> 2015-12-02 17:09:38.415305 7f9d9cd87900 5 asok(0x4dc0000) register_command 0 hook 0x4d5c0b0 -30> 2015-12-02 17:09:38.415313 7f9d9cd87900 5 asok(0x4dc0000) register_command version hook 0x4d5c0b0 -29> 2015-12-02 17:09:38.415316 7f9d9cd87900 5 asok(0x4dc0000) register_command git_version hook 0x4d5c0b0 -28> 2015-12-02 17:09:38.415319 7f9d9cd87900 5 asok(0x4dc0000) register_command help hook 0x4d60140 -27> 2015-12-02 17:09:38.415321 7f9d9cd87900 5 asok(0x4dc0000) register_command get_command_descriptions hook 0x4d60130 -26> 2015-12-02 17:09:38.415349 7f9d9cd87900 10 monclient(hunting): build_initial_monmap -25> 2015-12-02 17:09:38.415350 7f9d96e90700 5 asok(0x4dc0000) entry start -24> 2015-12-02 17:09:38.424345 7f9d9cd87900 5 adding auth protocol: cephx -23> 2015-12-02 17:09:38.424351 7f9d9cd87900 5 adding auth protocol: cephx -22> 2015-12-02 17:09:38.424416 7f9d9cd87900 5 asok(0x4dc0000) register_command objecter_requests hook 0x4d60170 -21> 2015-12-02 17:09:38.424475 7f9d9cd87900 1 -- 192.168.239.12:6800/5415 messenger.start -20> 2015-12-02 17:09:38.424499 7f9d9cd87900 1 -- :/0 messenger.start -19> 2015-12-02 17:09:38.424515 7f9d9cd87900 1 -- 192.168.239.12:6803/5415 messenger.start -18> 2015-12-02 17:09:38.424540 7f9d9cd87900 1 -- 192.168.239.12:6802/5415 messenger.start -17> 2015-12-02 17:09:38.424558 7f9d9cd87900 1 -- 192.168.239.12:6801/5415 messenger.start -16> 2015-12-02 17:09:38.424583 7f9d9cd87900 1 -- :/0 messenger.start -15> 2015-12-02 17:09:38.424618 7f9d9cd87900 2 osd.7 0 mounting /var/lib/ceph/osd/ceph-7 /var/lib/ceph/osd/ceph-7/journal -14> 2015-12-02 17:09:38.425040 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) backend xfs (magic 0x58465342) -13> 2015-12-02 17:09:38.427504 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: FIEMAP ioctl is supported and appears to work -12> 2015-12-02 17:09:38.427519 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option -11> 2015-12-02 17:09:38.491583 7f9d9cd87900 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_features: syncfs(2) syscall fully supported (by glibc and kernel) -10> 2015-12-02 17:09:38.491815 7f9d9cd87900 0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-7) detect_feature: extsize is supported and kernel 3.13.0-68-generic >= 3.5 -9> 2015-12-02 17:09:38.631694 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled -8> 2015-12-02 17:09:39.296226 7f9d9cd87900 2 journal open /var/lib/ceph/osd/ceph-7/journal fsid 6a094bb8-93d0-42e8-b429-439d6968f35c fs_op_seq 35890293 -7> 2015-12-02 17:09:39.303520 7f9d9cd87900 1 journal _open /var/lib/ceph/osd/ceph-7/journal fd 19: 10737418240 bytes, block size 4096 bytes, directio = 1, aio = 1 -6> 2015-12-02 17:09:39.304766 7f9d9cd87900 2 journal read_entry 8847163392 : seq 35890294 6423 bytes -5> 2015-12-02 17:09:39.304789 7f9d9cd87900 2 journal read_entry 8847163392 : seq 35890294 6423 bytes -4> 2015-12-02 17:09:39.304793 7f9d9cd87900 3 journal journal_replay: applying op seq 35890294 -3> 2015-12-02 17:09:39.305243 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) error (1) Operation not permitted not handled on operation 0x4f9b665 (35890294.0.0, or op 0, counting from 0) -2> 2015-12-02 17:09:39.305260 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) unexpected error code -1> 2015-12-02 17:09:39.305261 7f9d9cd87900 0 filestore(/var/lib/ceph/osd/ceph-7) transaction dump: { "ops": [ { "op_num": 0, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "0000004386.00000000000000976285": 176 } }, { "op_num": 1, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "_epoch": 4, "_info": 745 } }, { "op_num": 2, "op_name": "omap_setkeys", "collection": "1.ac_head", "oid": "ac\/\/head\/\/1", "attr_lens": { "0000004386.00000000000000976285": 176, "can_rollback_to": 12, "rollback_info_trimmed_to": 12 } }, { "op_num": 3, "op_name": "op_setallochint", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "expected_object_size": "4194304", "expected_write_size": "4194304" }, { "op_num": 4, "op_name": "write", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "length": 4096, "offset": 294912, "bufferlist length": 4096 }, { "op_num": 5, "op_name": "setattr", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "name": "_", "length": 267 }, { "op_num": 6, "op_name": "setattr", "collection": "1.ac_head", "oid": "9fda6eac\/rb.0.66897.2ae8944a.000000001020\/head\/\/1", "name": "snapset", "length": 31 } ] } 0> 2015-12-02 17:09:39.309384 7f9d9cd87900 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7f9d9cd87900 time 2015-12-02 17:09:39.305384 os/FileStore.cc: 2757: FAILED assert(0 == "unexpected error") ceph version 0.94.5 (9764da52395923e0b32908d83a9f7304401fee43) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0xbc60eb] 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa52) [0x923d12] 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x92a3a4] 4: (JournalingObjectStore::journal_replay(unsigned long)+0x5cb) [0x94355b] 5: (FileStore::mount()+0x3bb6) [0x9139f6] 6: (OSD::init()+0x259) [0x6c59b9] 7: (main()+0x2860) [0x6527e0] 8: (__libc_start_main()+0xf5) [0x7f9d99ec7ec5] 9: /usr/bin/ceph-osd() [0x66b887] |
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
