On Wed, Dec 2, 2015 at 11:11 AM, Major Csaba <major.csaba@xxxxxxxxxxx> wrote: > Hi, > [ sorry, I accidentaly left out the list address ] > > This is the content of the LOG file in the directory > /var/lib/ceph/osd/ceph-7/current/omap: > 2015/12/02-18:48:12.241386 7f805fc27900 Recovering log #26281 > 2015/12/02-18:48:12.242455 7f805fc27900 Level-0 table #26283: started > 2015/12/02-18:48:12.274615 7f805fc27900 Level-0 table #26283: 32841 bytes OK > 2015/12/02-18:48:12.352606 7f805fc27900 Delete type=2 #26282 > 2015/12/02-18:48:12.353143 7f805fc27900 Delete type=2 #26284 > 2015/12/02-18:48:12.353657 7f805fc27900 Delete type=2 #26285 > 2015/12/02-18:48:12.354145 7f805fc27900 Delete type=3 #26279 > 2015/12/02-18:48:12.354183 7f805fc27900 Delete type=0 #26281 > 2015/12/02-18:48:12.354343 7f80541a4700 Compacting 14@0 + 5@1 files > 2015/12/02-18:48:12.497244 7f80541a4700 Generated table #26285: 116539 keys, > 2134818 bytes > 2015/12/02-18:48:12.653044 7f80541a4700 Generated table #26286: 173429 keys, > 2130210 bytes > 2015/12/02-18:48:12.819800 7f80541a4700 Generated table #26287: 172490 keys, > 2130006 bytes > 2015/12/02-18:48:12.894106 7f80541a4700 compacted to: files[ 14 5 8 0 0 0 0 > ] > 2015/12/02-18:48:12.894115 7f80541a4700 Compaction error: Corruption: > corrupted compressed block contents > > I don't know if it's relevant, but seems wrong. Uh, yeah. Seems something has gone terribly wrong in or under leveldb. I'm not sure if there's any good way to repair that, or if you just need to figure out how it died (to prevent future recurrences) and rebuild the OSD. :/ -Greg > > Regards, > Csaba > > On 12/02/2015 07:54 PM, Major Csaba wrote: > > 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 > _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com