Project

General

Profile

Bug #11027 » osd_crash.log

Italo Santos, 03/05/2015 04:16 AM

 
-35> 2015-03-03 16:37:45.475310 7f33e0da4700 3 osd.8 4249 handle_osd_map epochs [4250,4250], i have 4249, src has [3708,4250]
-34> 2015-03-03 16:37:45.476313 7f33e0da4700 1 -- 10.31.52.11:6804/10590 <== osd.16 10.31.52.14:6802/4290 51 ==== pg_query(41.6 epoch 4250) v3 ==== 144+0+0 (699496627 0 0) 0x188e9680 con 0x1818ef20
-33> 2015-03-03 16:37:45.476381 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.475239, event: header_read, op: pg_query(41.6 epoch 4250)
-32> 2015-03-03 16:37:45.476389 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.475239, event: throttled, op: pg_query(41.6 epoch 4250)
-31> 2015-03-03 16:37:45.476393 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.475277, event: all_read, op: pg_query(41.6 epoch 4250)
-30> 2015-03-03 16:37:45.476397 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.476377, event: dispatched, op: pg_query(41.6 epoch 4250)
-29> 2015-03-03 16:37:45.476403 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.476403, event: waiting_for_osdmap, op: pg_query(41.6 epoch 4250)
-28> 2015-03-03 16:37:45.476412 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.476412, event: started, op: pg_query(41.6 epoch 4250)
-27> 2015-03-03 16:37:45.476395 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4245/4135) [16,8,4]/[16,8,11] r=1 lpr=4245 pi=4129-4244/7 luod=0'0 crt=4204'3555 lcod 0'0 active+remapped] exit Started/ReplicaActive/RepNotRecovering 6.774760 13 0.000326
-26> 2015-03-03 16:37:45.476434 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4245/4135) [16,8,4]/[16,8,11] r=1 lpr=4245 pi=4129-4244/7 luod=0'0 crt=4204'3555 lcod 0'0 active+remapped] exit Started/ReplicaActive 6.774820 0 0.000000
-25> 2015-03-03 16:37:45.476453 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4245/4135) [16,8,4]/[16,8,11] r=1 lpr=4245 pi=4129-4244/7 luod=0'0 crt=4204'3555 lcod 0'0 active+remapped] exit Started 7.797222 0 0.000000
-24> 2015-03-03 16:37:45.476468 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4245/4135) [16,8,4]/[16,8,11] r=1 lpr=4245 pi=4129-4244/7 luod=0'0 crt=4204'3555 lcod 0'0 active+remapped] enter Reset
-23> 2015-03-03 16:37:45.476572 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] exit Reset 0.000103 1 0.000141
-22> 2015-03-03 16:37:45.476596 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] enter Started
-21> 2015-03-03 16:37:45.476609 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] enter Start
-20> 2015-03-03 16:37:45.476619 7f33d9595700 1 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] state<Start>: transitioning to Stray
-19> 2015-03-03 16:37:45.476634 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] exit Start 0.000025 0 0.000000
-18> 2015-03-03 16:37:45.476647 7f33d9595700 5 osd.8 pg_epoch: 4250 pg[41.6( v 4204'3557 (4201'500,4204'3557] local-les=4246 n=1288 ec=2937 les/c 4246/4249 4244/4250/4135) [16,8,4] r=1 lpr=4250 pi=4129-4249/8 crt=4204'3555 lcod 0'0 inactive NOTIFY] enter Started/Stray
-17> 2015-03-03 16:37:45.476761 7f33e0da4700 5 -- op tracker -- seq: 556, time: 2015-03-03 16:37:45.476761, event: done, op: pg_query(41.6 epoch 4250)
-16> 2015-03-03 16:37:45.477632 7f33d9595700 1 -- 10.31.52.11:6804/10590 --> 10.31.52.14:6802/4290 -- osd_map(4250..4250 src has 3708..4250) v3 -- ?+0 0x18c41d40 con 0x1818ef20
-15> 2015-03-03 16:37:45.477656 7f33d9595700 1 -- 10.31.52.11:6804/10590 --> 10.31.52.14:6802/4290 -- pg_notify(41.6(8) epoch 4250) v5 -- ?+0 0x18c625a0 con 0x1818ef20
-14> 2015-03-03 16:37:45.478015 7f33d8d94700 1 -- 10.31.52.11:6804/10590 --> 10.31.52.14:6802/4290 -- pg_notify(41.6(8) epoch 4250) v5 -- ?+0 0x18504f00 con 0x1818ef20
-13> 2015-03-03 16:37:45.822498 7f33ced80700 1 -- 10.31.52.11:6804/10590 <== osd.17 10.31.52.10:6804/3819 33 ==== osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[]) v11 ==== 1210+0+16652 (2305286467 0 2719884670) 0x18ca9700 con 0x180db340
-12> 2015-03-03 16:37:45.822594 7f33ced80700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.822196, event: header_read, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-11> 2015-03-03 16:37:45.822613 7f33ced80700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.822198, event: throttled, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-10> 2015-03-03 16:37:45.822626 7f33ced80700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.822490, event: all_read, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-9> 2015-03-03 16:37:45.822634 7f33ced80700 5 -- op tracker -- seq: 557, time: 0.000000, event: dispatched, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-8> 2015-03-03 16:37:45.822782 7f33d4d8c700 1 -- 10.31.52.11:6804/10590 --> 10.31.52.10:6804/3819 -- osd_map(4250..4250 src has 3708..4250) v3 -- ?+0 0x18d80240 con 0x180db340
-7> 2015-03-03 16:37:45.822867 7f33d4d8c700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.822867, event: reached_pg, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-6> 2015-03-03 16:37:45.822896 7f33d4d8c700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.822895, event: started, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-5> 2015-03-03 16:37:45.823032 7f33d4d8c700 5 -- op tracker -- seq: 557, time: 2015-03-03 16:37:45.823032, event: done, op: osd_sub_op(unknown.0.0:0 36.70s0 0//0//-1 [scrub-map] v 0'0 snapset=0=[]:[] snapc=0=[])
-4> 2015-03-03 16:37:45.823197 7f33d2d88700 2 osd.8 pg_epoch: 4250 pg[36.70s0( v 4231'23590 (4204'20583,4231'23590] local-les=4246 n=1675 ec=2884 les/c 4246/4246 4244/4245/4245) [8,17,11] r=0 lpr=4245 crt=4231'23588 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep] scrub_compare_maps osd.8 has 24 items
-3> 2015-03-03 16:37:45.823227 7f33d2d88700 2 osd.8 pg_epoch: 4250 pg[36.70s0( v 4231'23590 (4204'20583,4231'23590] local-les=4246 n=1675 ec=2884 les/c 4246/4246 4244/4245/4245) [8,17,11] r=0 lpr=4245 crt=4231'23588 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep] scrub_compare_maps replica 11(2) has 24 items
-2> 2015-03-03 16:37:45.823243 7f33d2d88700 2 osd.8 pg_epoch: 4250 pg[36.70s0( v 4231'23590 (4204'20583,4231'23590] local-les=4246 n=1675 ec=2884 les/c 4246/4246 4244/4245/4245) [8,17,11] r=0 lpr=4245 crt=4231'23588 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep] scrub_compare_maps replica 17(1) has 24 items
-1> 2015-03-03 16:37:45.823770 7f33d2d88700 2 osd.8 pg_epoch: 4250 pg[36.70s0( v 4231'23590 (4204'20583,4231'23590] local-les=4246 n=1675 ec=2884 les/c 4246/4246 4244/4245/4245) [8,17,11] r=0 lpr=4245 crt=4231'23588 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep]
0> 2015-03-03 16:37:45.830113 7f33d2d88700 -1 osd/ReplicatedPG.cc: In function 'void ReplicatedPG::issue_repop(ReplicatedPG::RepGather*, utime_t)' thread 7f33d2d88700 time 2015-03-03 16:37:45.824219
osd/ReplicatedPG.cc: 7494: FAILED assert(!i->mod_desc.empty())

ceph version 0.92 (00a3ac3b67d93860e7f0b6e07319f11b14d0fec0)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x72) [0xcc86c2]
2: (ReplicatedPG::issue_repop(ReplicatedPG::RepGather*, utime_t)+0x49c) [0x9624fc]
3: (ReplicatedPG::simple_repop_submit(ReplicatedPG::RepGather*)+0x7a) [0x9698ba]
4: (ReplicatedPG::_scrub(ScrubMap&)+0x2e62) [0x99b072]
5: (PG::scrub_compare_maps()+0x511) [0x90f0d1]
6: (PG::chunky_scrub(ThreadPool::TPHandle&)+0x204) [0x910bb4]
7: (PG::scrub(ThreadPool::TPHandle&)+0x3a3) [0x912c53]
8: (OSD::ScrubWQ::_process(PG*, ThreadPool::TPHandle&)+0x13) [0x7ebdd3]
9: (ThreadPool::worker(ThreadPool::WorkThread*)+0x629) [0xcbade9]
10: (ThreadPool::WorkThread::entry()+0x10) [0xcbbfe0]
11: (()+0x6b50) [0x7f33f54a5b50]
12: (clone()+0x6d) [0x7f33f3ec17bd]
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
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.8.log
--- end dump of recent events ---
2015-03-03 16:37:45.910335 7f33d2d88700 -1 *** Caught signal (Aborted) **
in thread 7f33d2d88700

ceph version 0.92 (00a3ac3b67d93860e7f0b6e07319f11b14d0fec0)
1: /usr/bin/ceph-osd() [0xbde9fc]
2: (()+0xf0a0) [0x7f33f54ae0a0]
3: (gsignal()+0x35) [0x7f33f3e17165]
4: (abort()+0x180) [0x7f33f3e1a3e0]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f33f466e89d]
6: (()+0x63996) [0x7f33f466c996]
7: (()+0x639c3) [0x7f33f466c9c3]
8: (()+0x63bee) [0x7f33f466cbee]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x220) [0xcc8870]
10: (ReplicatedPG::issue_repop(ReplicatedPG::RepGather*, utime_t)+0x49c) [0x9624fc]
11: (ReplicatedPG::simple_repop_submit(ReplicatedPG::RepGather*)+0x7a) [0x9698ba]
12: (ReplicatedPG::_scrub(ScrubMap&)+0x2e62) [0x99b072]
13: (PG::scrub_compare_maps()+0x511) [0x90f0d1]
14: (PG::chunky_scrub(ThreadPool::TPHandle&)+0x204) [0x910bb4]
15: (PG::scrub(ThreadPool::TPHandle&)+0x3a3) [0x912c53]
16: (OSD::ScrubWQ::_process(PG*, ThreadPool::TPHandle&)+0x13) [0x7ebdd3]
17: (ThreadPool::worker(ThreadPool::WorkThread*)+0x629) [0xcbade9]
18: (ThreadPool::WorkThread::entry()+0x10) [0xcbbfe0]
19: (()+0x6b50) [0x7f33f54a5b50]
20: (clone()+0x6d) [0x7f33f3ec17bd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
-4> 2015-03-03 16:37:45.870794 7f33dcd9c700 1 -- 10.31.52.11:6805/10590 <== osd.11 10.31.52.12:0/4513 4 ==== osd_ping(ping e4250 stamp 2015-03-03 16:37:45.867410) v2 ==== 47+0+0 (3074464048 0 0) 0x18cf2f00 con 0x1875e6e0
-3> 2015-03-03 16:37:45.870819 7f33dcd9c700 1 -- 10.31.52.11:6805/10590 --> 10.31.52.12:0/4513 -- osd_ping(ping_reply e4250 stamp 2015-03-03 16:37:45.867410) v2 -- ?+0 0x52dd4a0 con 0x1875e6e0
-2> 2015-03-03 16:37:45.870909 7f33de59f700 1 -- 10.32.30.11:6805/10590 <== osd.11 10.31.52.12:0/4513 4 ==== osd_ping(ping e4250 stamp 2015-03-03 16:37:45.867410) v2 ==== 47+0+0 (3074464048 0 0) 0x18cf34a0 con 0x1875f4a0
-1> 2015-03-03 16:37:45.870932 7f33de59f700 1 -- 10.32.30.11:6805/10590 --> 10.31.52.12:0/4513 -- osd_ping(ping_reply e4250 stamp 2015-03-03 16:37:45.867410) v2 -- ?+0 0x18c63680 con 0x1875f4a0
0> 2015-03-03 16:37:45.910335 7f33d2d88700 -1 *** Caught signal (Aborted) **
in thread 7f33d2d88700

ceph version 0.92 (00a3ac3b67d93860e7f0b6e07319f11b14d0fec0)
1: /usr/bin/ceph-osd() [0xbde9fc]
2: (()+0xf0a0) [0x7f33f54ae0a0]
3: (gsignal()+0x35) [0x7f33f3e17165]
4: (abort()+0x180) [0x7f33f3e1a3e0]
5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f33f466e89d]
6: (()+0x63996) [0x7f33f466c996]
7: (()+0x639c3) [0x7f33f466c9c3]
8: (()+0x63bee) [0x7f33f466cbee]
9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x220) [0xcc8870]
10: (ReplicatedPG::issue_repop(ReplicatedPG::RepGather*, utime_t)+0x49c) [0x9624fc]
11: (ReplicatedPG::simple_repop_submit(ReplicatedPG::RepGather*)+0x7a) [0x9698ba]
12: (ReplicatedPG::_scrub(ScrubMap&)+0x2e62) [0x99b072]
13: (PG::scrub_compare_maps()+0x511) [0x90f0d1]
14: (PG::chunky_scrub(ThreadPool::TPHandle&)+0x204) [0x910bb4]
15: (PG::scrub(ThreadPool::TPHandle&)+0x3a3) [0x912c53]
16: (OSD::ScrubWQ::_process(PG*, ThreadPool::TPHandle&)+0x13) [0x7ebdd3]
17: (ThreadPool::worker(ThreadPool::WorkThread*)+0x629) [0xcbade9]
18: (ThreadPool::WorkThread::entry()+0x10) [0xcbbfe0]
19: (()+0x6b50) [0x7f33f54a5b50]
20: (clone()+0x6d) [0x7f33f3ec17bd]
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
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.8.log
--- end dump of recent events ---
(1-1/2)