Actions
Bug #496
closedosd: OSDMap::decode / PG::read_log
Status:
Closed
Priority:
Normal
Assignee:
-
Category:
OSD
Target version:
-
% Done:
0%
Source:
Tags:
Backport:
Regression:
Severity:
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
This morning I found out that 4 of my 12 OSD's had crashed at almost exactly the same moment, all with the following backtrace.
Core was generated by `/usr/bin/cosd -i 5 -c /etc/ceph/ceph.conf'.
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000000000 in ?? ()
(gdb) bt
#0 0x0000000000000000 in ?? ()
#1 0x00000000005d96a1 in sigabrt_handler (signum=6) at config.cc:238
#2 <signal handler called>
#3 0x00007fd16e61fa75 in raise () from /lib/libc.so.6
#4 0x00007fd16e6235c0 in abort () from /lib/libc.so.6
#5 0x00007fd16eed58e5 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/libstdc++.so.6
#6 0x00007fd16eed3d16 in ?? () from /usr/lib/libstdc++.so.6
#7 0x00007fd16eed3d43 in std::terminate() () from /usr/lib/libstdc++.so.6
#8 0x00007fd16eed3e3e in __cxa_throw () from /usr/lib/libstdc++.so.6
#9 0x000000000045ae8e in ceph::buffer::list::iterator::advance (this=0x7fd1679ac970, len=2, dest=0x7fd1679aca4e "\001")
at ./include/buffer.h:593
#10 ceph::buffer::list::iterator::copy (this=0x7fd1679ac970, len=2, dest=0x7fd1679aca4e "\001") at ./include/buffer.h:640
#11 0x000000000051ff2f in OSDMap::decode(ceph::buffer::list&) ()
#12 0x00000000004e5add in OSD::get_map (this=0x293a000, epoch=468) at osd/OSD.cc:2980
#13 0x00000000004ee8e4 in OSD::advance_map (this=0x293a000, t=<value optimized out>) at osd/OSD.cc:2665
#14 0x00000000004f2b86 in OSD::handle_osd_map (this=0x293a000, m=<value optimized out>) at osd/OSD.cc:2498
#15 0x00000000004f4138 in OSD::_dispatch (this=0x293a000, m=0x4bd9400) at osd/OSD.cc:2082
#16 0x00000000004f4b89 in OSD::ms_dispatch (this=0x293a000, m=0x4bd9400) at osd/OSD.cc:1962
#17 0x00000000004608f9 in Messenger::ms_deliver_dispatch (this=0x2938000) at msg/Messenger.h:97
#18 SimpleMessenger::dispatch_entry (this=0x2938000) at msg/SimpleMessenger.cc:342
#19 0x000000000045a04c in SimpleMessenger::DispatchThread::entry (this=0x2938488) at msg/SimpleMessenger.h:558
#20 0x000000000046e63a in Thread::_entry_func (arg=0x2319) at ./common/Thread.h:39
#21 0x00007fd16f71a9ca in start_thread () from /lib/libpthread.so.0
#22 0x00007fd16e6d26fd in clone () from /lib/libc.so.6
#23 0x0000000000000000 in ?? ()
osd3, osd5, osd6 and osd7 went down with this message.
When I started the OSD again, they would crash again with the following backtrace:
Core was generated by `/usr/bin/cosd -i 6 -c /etc/ceph/ceph.conf'.
Program terminated with signal 11, Segmentation fault.
#0 0x0000000000000000 in ?? ()
(gdb) bt
#0 0x0000000000000000 in ?? ()
#1 0x00000000005d97b1 in sigsegv_handler (signum=11) at config.cc:229
#2 <signal handler called>
#3 0x0000000000000000 in ?? ()
#4 0x00000000005d96a1 in sigabrt_handler (signum=6) at config.cc:238
#5 <signal handler called>
#6 0x00007f72b2234a75 in raise () from /lib/libc.so.6
#7 0x00007f72b22385c0 in abort () from /lib/libc.so.6
#8 0x00007f72b2aea8e5 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/libstdc++.so.6
#9 0x00007f72b2ae8d16 in ?? () from /usr/lib/libstdc++.so.6
#10 0x00007f72b2ae8d43 in std::terminate() () from /usr/lib/libstdc++.so.6
#11 0x00007f72b2ae8e3e in __cxa_throw () from /usr/lib/libstdc++.so.6
#12 0x00000000005c6f88 in ceph::__ceph_assert_fail (assertion=0x608357 "0", file=<value optimized out>, line=2174,
func=<value optimized out>) at common/assert.cc:30
#13 0x0000000000537813 in PG::read_log (this=0xb70d00, store=<value optimized out>) at osd/PG.cc:2174
#14 0x000000000053a286 in PG::read_state (this=<value optimized out>, store=<value optimized out>) at osd/PG.cc:2382
#15 0x00000000004e448c in OSD::load_pgs (this=0xb2a000) at osd/OSD.cc:981
#16 0x00000000004f504f in OSD::init (this=0xb2a000) at osd/OSD.cc:502
#17 0x0000000000458dc2 in main (argc=<value optimized out>, argv=<value optimized out>) at cosd.cc:292
From the first crash I don't have detailed logging, but I do have that from the second.
2010-10-16 10:50:37.564442 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/1.0p6_head 'ondisklog' = 17 2010-10-16 10:50:37.564461 7f72b395e720 osd6 467 pg[1.0p6( empty n=0 ec=2 les=455 453/453/423) [] r=0 mlcod 0'0 inactive] read_log 0~0 2010-10-16 10:50:37.564476 7f72b395e720 osd6 467 pg[1.0p6( empty n=0 ec=2 les=455 453/453/423) [] r=0 mlcod 0'0 inactive] read_log done 2010-10-16 10:50:37.564493 7f72b395e720 osd6 467 load_pgs loaded pg[1.0p6( empty n=0 ec=2 les=455 453/453/423) []/[6,11,9] r=0 mlcod 0'0 inactive] log(0'0,0'0] 2010-10-16 10:50:37.564510 7f72b395e720 osd6 467 _open_lock_pg 3.2f8 2010-10-16 10:50:37.564520 7f72b395e720 osd6 467 _get_pool 3 2 -> 3 2010-10-16 10:50:37.564563 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'info' 2010-10-16 10:50:37.564615 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'info' = 281 2010-10-16 10:50:37.564629 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'snap_collections' 2010-10-16 10:50:37.564651 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'snap_collections' = 5 2010-10-16 10:50:37.564663 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'ondisklog' 2010-10-16 10:50:37.564684 7f72b395e720 filestore(/srv/ceph/osd.6) collection_getattr /srv/ceph/osd.6/current/3.2f8_head 'ondisklog' = 17 2010-10-16 10:50:37.564694 7f72b395e720 osd6 467 pg[3.2f8( v 467'680 (467'678,467'680] n=163 ec=2 les=456 453/453/453) [] r=0 (info mismatch, log(0'0,0'0]) lcod 0'0 mlcod 0'0 inactive] read_log 60840~270 2010-10-16 10:50:37.564715 7f72b395e720 filestore(/srv/ceph/osd.6) read /srv/ceph/osd.6/current/meta/pglog_3.2f8_0 60840~270 2010-10-16 10:50:37.564748 7f72b395e720 filestore(/srv/ceph/osd.6) read /srv/ceph/osd.6/current/meta/pglog_3.2f8_0 60840~270 = 0 2010-10-16 10:50:37.564759 7f72b395e720 osd6 467 pg[3.2f8( v 467'680 (467'678,467'680] n=163 ec=2 les=456 453/453/453) [] r=0 (info mismatch, log(467'678,0'0]) (log bound mismatch, empty) lcod 0'0 mlcod 0'0 inactive] read_log got 0 bytes, expected 61110-60840=270 osd/PG.cc: In function 'void PG::read_log(ObjectStore*)': osd/PG.cc:2174: FAILED assert(0) ceph version 0.22~rc (53decffc7e30fb70cd49da2382db00698913961c) 1: (PG::read_state(ObjectStore*)+0x6f6) [0x53a286] 2: (OSD::load_pgs()+0x15c) [0x4e448c] 3: (OSD::init()+0x48f) [0x4f504f] 4: (main()+0x1de2) [0x458dc2] 5: (__libc_start_main()+0xfd) [0x7f72b221fc4d] 6: /usr/bin/cosd() [0x456dc9] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this. *** Caught signal (ABRT) *** ceph version 0.22~rc (53decffc7e30fb70cd49da2382db00698913961c) 1: (sigabrt_handler(int)+0x7d) [0x5d966d] 2: (()+0x33af0) [0x7f72b2234af0] 3: (gsignal()+0x35) [0x7f72b2234a75] 4: (abort()+0x180) [0x7f72b22385c0] 5: (__gnu_cxx::__verbose_terminate_handler()+0x115) [0x7f72b2aea8e5] 6: (()+0xcad16) [0x7f72b2ae8d16] 7: (()+0xcad43) [0x7f72b2ae8d43] 8: (()+0xcae3e) [0x7f72b2ae8e3e] 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x448) [0x5c6f88] 10: (PG::read_log(ObjectStore*)+0x2c3) [0x537813] 11: (PG::read_state(ObjectStore*)+0x6f6) [0x53a286] 12: (OSD::load_pgs()+0x15c) [0x4e448c] 13: (OSD::init()+0x48f) [0x4f504f] 14: (main()+0x1de2) [0x458dc2] 15: (__libc_start_main()+0xfd) [0x7f72b221fc4d] 16: /usr/bin/cosd() [0x456dc9] *** Caught signal (SEGV) *** ceph version 0.22~rc (53decffc7e30fb70cd49da2382db00698913961c) 1: (sigsegv_handler(int)+0x7d) [0x5d977d] 2: (()+0x33af0) [0x7f72b2234af0]
I checked the pglog, but it isn't empty at all?
root@node07:~# stat /srv/ceph/osd.6/current/meta/pglog_3.2f8_0 File: `/srv/ceph/osd.6/current/meta/pglog_3.2f8_0' Size: 56430 Blocks: 112 IO Block: 4096 regular file Device: 18h/24d Inode: 276278 Links: 1 Access: (0644/-rw-r--r--) Uid: ( 0/ root) Gid: ( 0/ root) Access: 2010-10-13 10:09:45.693902491 +0200 Modify: 2010-10-15 23:59:19.295518111 +0200 Change: 2010-10-15 23:59:19.295518111 +0200 root@node07:~#
What I did notice is that the disk of this OSD is pretty full:
root@node07:~# df -h /srv/ceph/osd.6 Filesystem Size Used Avail Use% Mounted on /dev/mapper/data-osd 272G 271G 1.7G 100% /srv/ceph/osd.6 root@node07:~#
Same goes for the other OSD's, they are also near full.
The "full flag" has been set, could that be the root of this issue?
I've uploaded all the relevant cores (preserved the timestamps), binaries (with debug symbols) and logs to logger.ceph.widodh.nl:/srv/ceph/issues/osd_crash_osdmap_decode
Updated by Sage Weil over 13 years ago
This all looks like fallout from a full disk and failed writes.
The unstable branch has some code to handle corrupt pg logs; you can switch to that. Not before clearing up some space, though!
Until we have graceful ENOSPC handling, we should probably make the low-level functions assert(0) on any ENOSPC.
Updated by Sage Weil over 13 years ago
See fd42c8527be21923d633b253a3260e1e600c1853 and 19c2c8332915c323defb2ff2e62bee2e7a3db845. These will prevent you from doing any damage on ENOSPC next time.
Depending on what the damage was here, things may or may not be recoverable (using unstable). (This is all assuming ENOSPC was the culprit here, but it really sounds like it was.)
The other question is how we were doing I/O despite the full flag being set in the osdmap. :)
Updated by Sage Weil over 13 years ago
- Status changed from New to Closed
See #502. Closing this one out.
Actions