Re: OSD crash, unable to restart

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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.

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

[Index of Archives]     [Information on CEPH]     [Linux Filesystem Development]     [Ceph Development]     [Ceph Large]     [Ceph Dev]     [Linux USB Development]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [xfs]


  Powered by Linux