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]
|
