Having trouble submitting an issue in the redmine tracker at the moment... just spitting back 'Internal Error, see administrator'. Below is the problem description and how to reproduce. Applicable files are here: http://learnitwithme.com/share/ceph1-Locker.cc-1459-failed-assert.tar.bz2 http://learnitwithme.com/share/ceph2-Locker.cc-1459-failed-assert.tar.bz2 http://learnitwithme.com/share/ceph3-Locker.cc-1459-failed-assert.tar.bz2 *********************************** Ceph filesystem with snapshot crashes mds when active is shut down and standby takes over. This is a basic 3 node cluster with mon,mds,osd running on each node, along with a single client connected. Including corefiles, logs, and conf. <pre> ceph 1: mkcephfs -a -c /etc/ceph/ceph.conf --mkbtrfs ceph1, ceph2, ceph3: service ceph start Client: mount -t ceph 10.10.10.91,10.10.10.92,10.10.10.93:/ /mnt cd /mnt rsync -a /usr/lib . mkdir .snap/daily rm -rf lib rsync -a /lib/modules . ceph 2: [root@ceph2 ~]# ceph mds stat 2011-07-24 21:59:19.326608 mon <- [mds,stat] 2011-07-24 21:59:19.328114 mon0 -> 'e6: 1/1/1 up {0=ceph2=up:active}, 2 up:standby' (0) [root@ceph2 ~]# service ceph stop mds === mds.ceph2 === Stopping Ceph mds.ceph2 on ceph2...kill 2984...done [root@ceph2 ~]# ceph mds stat 2011-07-24 21:59:55.377053 mon <- [mds,stat] 2011-07-24 21:59:55.377720 mon1 -> 'e10: 1/1/1 up {0=ceph1=up:active}, 1 up:standby' (0) ceph 1: [root@ceph1 ~]# service ceph status === mon.ceph1 === running... === mds.ceph1 === dead. === osd.0 === running... [root@ceph1 ~]# ceph mds stat 2011-07-24 22:01:58.770243 mon <- [mds,stat] 2011-07-24 22:01:58.771013 mon0 -> 'e19: 1/1/1 up {0=ceph3=up:active(laggy or crashed)}' (0) ceph 2: [root@ceph2 ~]# service ceph start mds === mds.ceph2 === Starting Ceph mds.ceph2 on ceph2... ** WARNING: Ceph is still under development. Any feedback can be directed ** ** at ceph-devel@xxxxxxxxxxxxxxx or http://ceph.newdream.net/. ** starting mds.ceph2 at 0.0.0.0:6800/3462 [root@ceph2 ~]# ceph mds stat 2011-07-24 22:04:15.111478 mon <- [mds,stat] 2011-07-24 22:04:15.112092 mon1 -> 'e29: 1/1/1 up {0=ceph2=up:active(laggy or crashed)}' (0) On Sat, Jul 23, 2011 at 4:28 PM, Marcus Sorensen <shadowsor@xxxxxxxxx> wrote: > Yeah, I've got a few VMs set up to play with. Sort of painful having > multiple VMs write twice with the hard disk journal. > > I'm certain now that I can duplicate this, so I'll start fresh again > once more and keep track of the steps. > > Replying-all this time... > > On Sat, Jul 23, 2011 at 3:55 PM, Sage Weil <sage@xxxxxxxxxxxx> wrote: >> On Fri, 22 Jul 2011, Marcus Sorensen wrote: >>> Should these be reported here or perhaps through the tracker? >> >> It would be great if you could add this to the tracker with a detail >> description of how you hit the bug and whatever logs you have available. >> On-list is fine too, just a bit more work on our end. >> >> We haven't done a lot of MDS restart testing with snapshot workloads, so >> this isn't terribly surprising. I'm happy to hear you were able to work >> around it, though! >> >>> Just a >>> warning, I'm going to purposely be trying to break things and figuring >>> out how to recover (or at least what never to do :), so now's probably >>> a good time to set me straight on procedure. >>> >>> i was fiddling with my test cluster tonight and ran into this. >>> Basically I decided to reboot the cluster, and after reboot I had to >>> play a bit with the journals to get things going again. I didn't >>> realize that putting them on tmpfs would require me to touch the file, >> >> Putting the journals on tmpfs is not a good idea. The OSD considers >> anything journaled safe and durable, so you're exposing yourself to data >> loss in the event of a power failure. Hopefully this is a temporary thing >> to simulate an SSD or NVRAM journal...? :) >> >> sage >> >> >>> pull down the monmap, run 'cosd -i <num> --monmap <monmap> >>> --mkjournal' before the osds could come online. For some reason I had >>> the impression it would create the journal... I did something like >>> 'service ceph start', saw that the osd was mounted but cosd failed, >>> pulled monmap, recreated journal, then 'service ceph start osd.<num>'. >>> After getting these online I noticed the mds services were crashing on >>> all three nodes like so. Notice also that there were some clients >>> connected prior. >>> >>> [root@ceph3 ~]# 2011-07-22 23:03:57.640115 7f27d02cd700 mds-1.0 >>> handle_mds_map standby >>> 2011-07-22 23:04:21.928388 7f27d02cd700 mds-1.0 handle_mds_map standby >>> 2011-07-22 23:04:22.164395 7f27d02cd700 mds-1.0 handle_mds_map standby >>> 2011-07-22 23:04:37.634939 7f27d02cd700 mds0.22 handle_mds_map i am now mds0.22 >>> 2011-07-22 23:04:37.634967 7f27d02cd700 mds0.22 handle_mds_map state >>> change up:standby --> up:replay >>> 2011-07-22 23:04:37.634975 7f27d02cd700 mds0.22 replay_start >>> 2011-07-22 23:04:37.634984 7f27d02cd700 mds0.22 recovery set is >>> 2011-07-22 23:04:37.634990 7f27d02cd700 mds0.22 need osdmap epoch 131, have 128 >>> 2011-07-22 23:04:37.634995 7f27d02cd700 mds0.22 waiting for osdmap >>> 131 (which blacklists prior instance) >>> 2011-07-22 23:04:37.635027 7f27d02cd700 mds0.cache handle_mds_failure >>> mds0 : recovery peers are >>> 2011-07-22 23:04:37.644053 7f27d02cd700 mds0.22 ms_handle_connect on >>> 10.10.10.93:6801/3468 >>> 2011-07-22 23:04:37.649460 7f27d02cd700 mds0.22 ms_handle_connect on >>> 10.10.10.91:6801/4314 >>> 2011-07-22 23:04:37.654568 7f27d02cd700 mds0.22 ms_handle_connect on >>> 10.10.10.92:6803/4193 >>> 2011-07-22 23:04:37.725419 7f27d02cd700 mds0.cache creating system >>> inode with ino:100 >>> 2011-07-22 23:04:37.725542 7f27d02cd700 mds0.cache creating system >>> inode with ino:1 >>> 2011-07-22 23:04:39.223574 7f27cdbc2700 mds0.22 replay_done >>> 2011-07-22 23:04:39.223636 7f27cdbc2700 mds0.22 making mds journal writeable >>> 2011-07-22 23:04:39.239472 7f27d02cd700 mds0.22 handle_mds_map i am now mds0.22 >>> 2011-07-22 23:04:39.239768 7f27d02cd700 mds0.22 handle_mds_map state >>> change up:replay --> up:reconnect >>> 2011-07-22 23:04:39.239981 7f27d02cd700 mds0.22 reconnect_start >>> 2011-07-22 23:04:39.240187 7f27d02cd700 mds0.22 reopen_log >>> 2011-07-22 23:04:39.240399 7f27d02cd700 mds0.server reconnect_clients >>> -- 3 sessions >>> 2011-07-22 23:05:27.040962 7f27cf0c9700 mds0.server reconnect gave up >>> on client4108 10.10.10.99:0/1929168255 >>> 2011-07-22 23:05:27.041021 7f27cf0c9700 mds0.server reconnect gave up >>> on client4906 10.10.10.99:0/3243338282 >>> 2011-07-22 23:05:27.041038 7f27cf0c9700 mds0.server reconnect gave up >>> on client5114 10.10.10.99:0/2910973772 >>> 2011-07-22 23:05:27.041104 7f27cf0c9700 mds0.22 reconnect_done >>> 2011-07-22 23:05:27.061458 7f27d02cd700 mds0.22 handle_mds_map i am now mds0.22 >>> 2011-07-22 23:05:27.061480 7f27d02cd700 mds0.22 handle_mds_map state >>> change up:reconnect --> up:rejoin >>> 2011-07-22 23:05:27.061490 7f27d02cd700 mds0.22 rejoin_joint_start >>> 2011-07-22 23:05:27.161091 7f27d02cd700 mds0.22 rejoin_done >>> 2011-07-22 23:05:27.181033 7f27d02cd700 mds0.22 handle_mds_map i am now mds0.22 >>> 2011-07-22 23:05:27.181092 7f27d02cd700 mds0.22 handle_mds_map state >>> change up:rejoin --> up:active >>> 2011-07-22 23:05:27.181107 7f27d02cd700 mds0.22 recovery_done -- >>> successful recovery! >>> 2011-07-22 23:05:27.188878 7f27d02cd700 mds0.22 active_start >>> 2011-07-22 23:05:27.191328 7f27d02cd700 mds0.22 cluster recovered. >>> mds/Locker.cc: In function 'bool Locker::issue_caps(CInode*, >>> Capability*)', in thread '0x7f27d02cd700' >>> mds/Locker.cc: 1459: FAILED assert(in->is_head()) >>> ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278) >>> 1: (Locker::issue_caps(CInode*, Capability*)+0x1a0c) [0x5b25dc] >>> 2: (Locker::issue_caps_set(std::set<CInode*, std::less<CInode*>, >>> std::allocator<CInode*> >&)+0x26) [0x5b3ff6] >>> 3: (Locker::file_update_finish(CInode*, Mutation*, bool, client_t, >>> Capability*, MClientCaps*)+0x665) [0x5c2a45] >>> 4: (C_Locker_FileUpdate_finish::finish(int)+0x2c) [0x5d6b1c] >>> 5: (finish_contexts(CephContext*, std::list<Context*, >>> std::allocator<Context*> >&, int)+0xd0) [0x591250] >>> 6: (Journaler::_finish_flush(int, unsigned long, utime_t)+0x20e) [0x6ac6be] >>> 7: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xa8e) [0x69290e] >>> 8: (MDS::handle_core_message(Message*)+0x86f) [0x49e67f] >>> 9: (MDS::_dispatch(Message*)+0x2aa) [0x49e99a] >>> 10: (MDS::ms_dispatch(Message*)+0x6d) [0x4a060d] >>> 11: (SimpleMessenger::dispatch_entry()+0x8a1) [0x6f45b1] >>> 12: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x4806ac] >>> 13: (()+0x77e1) [0x7f27d354a7e1] >>> 14: (clone()+0x6d) [0x7f27d2b048ed] >>> ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278) >>> 1: (Locker::issue_caps(CInode*, Capability*)+0x1a0c) [0x5b25dc] >>> 2: (Locker::issue_caps_set(std::set<CInode*, std::less<CInode*>, >>> std::allocator<CInode*> >&)+0x26) [0x5b3ff6] >>> 3: (Locker::file_update_finish(CInode*, Mutation*, bool, client_t, >>> Capability*, MClientCaps*)+0x665) [0x5c2a45] >>> 4: (C_Locker_FileUpdate_finish::finish(int)+0x2c) [0x5d6b1c] >>> 5: (finish_contexts(CephContext*, std::list<Context*, >>> std::allocator<Context*> >&, int)+0xd0) [0x591250] >>> 6: (Journaler::_finish_flush(int, unsigned long, utime_t)+0x20e) [0x6ac6be] >>> 7: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xa8e) [0x69290e] >>> 8: (MDS::handle_core_message(Message*)+0x86f) [0x49e67f] >>> 9: (MDS::_dispatch(Message*)+0x2aa) [0x49e99a] >>> 10: (MDS::ms_dispatch(Message*)+0x6d) [0x4a060d] >>> 11: (SimpleMessenger::dispatch_entry()+0x8a1) [0x6f45b1] >>> 12: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x4806ac] >>> 13: (()+0x77e1) [0x7f27d354a7e1] >>> 14: (clone()+0x6d) [0x7f27d2b048ed] >>> *** Caught signal (Aborted) ** >>> in thread 0x7f27d02cd700 >>> ceph version 0.31 (commit:9019c6ce64053ad515a493e912e2e63ba9b8e278) >>> 1: /usr/bin/cmds() [0x747ea9] >>> 2: (()+0xf4c0) [0x7f27d35524c0] >>> 3: (gsignal()+0x35) [0x7f27d2a559a5] >>> 4: (abort()+0x175) [0x7f27d2a57185] >>> 5: (__gnu_cxx::__verbose_terminate_handler()+0x12d) [0x7f27d32faaad] >>> 6: (()+0xbcc36) [0x7f27d32f8c36] >>> 7: (()+0xbcc63) [0x7f27d32f8c63] >>> 8: (()+0xbcd5e) [0x7f27d32f8d5e] >>> 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char >>> const*)+0x3a7) [0x6c6a47] >>> 10: (Locker::issue_caps(CInode*, Capability*)+0x1a0c) [0x5b25dc] >>> 11: (Locker::issue_caps_set(std::set<CInode*, std::less<CInode*>, >>> std::allocator<CInode*> >&)+0x26) [0x5b3ff6] >>> 12: (Locker::file_update_finish(CInode*, Mutation*, bool, client_t, >>> Capability*, MClientCaps*)+0x665) [0x5c2a45] >>> 13: (C_Locker_FileUpdate_finish::finish(int)+0x2c) [0x5d6b1c] >>> 14: (finish_contexts(CephContext*, std::list<Context*, >>> std::allocator<Context*> >&, int)+0xd0) [0x591250] >>> 15: (Journaler::_finish_flush(int, unsigned long, utime_t)+0x20e) [0x6ac6be] >>> 16: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xa8e) [0x69290e] >>> 17: (MDS::handle_core_message(Message*)+0x86f) [0x49e67f] >>> 18: (MDS::_dispatch(Message*)+0x2aa) [0x49e99a] >>> 19: (MDS::ms_dispatch(Message*)+0x6d) [0x4a060d] >>> 20: (SimpleMessenger::dispatch_entry()+0x8a1) [0x6f45b1] >>> 21: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x4806ac] >>> 22: (()+0x77e1) [0x7f27d354a7e1] >>> 23: (clone()+0x6d) [0x7f27d2b048ed] >>> >>> >>> >>> 2011-07-22 23:18:55.727738 mds e196: 1/1/1 up >>> {0=ceph3=up:active(laggy or crashed)}, 1 up:standby >>> 2011-07-22 23:18:55.742299 osd e140: 3 osds: 3 up, 3 in >>> 2011-07-22 23:18:55.743943 mds e197: 1/1/1 up {0=ceph3=up:replay} >>> 2011-07-22 23:18:55.758649 pg v957: 594 pgs: 594 active+clean; 3760 >>> MB data, 13164 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:18:55.792549 log 2011-07-22 23:18:58.459865 mon0 >>> 10.10.10.91:6789/0 26 : [INF] mds? 10.10.10.93:6800/4702 up:boot >>> 2011-07-22 23:18:57.304880 mds e198: 1/1/1 up {0=ceph3=up:reconnect} >>> 2011-07-22 23:18:57.367480 log 2011-07-22 23:19:00.037792 mon0 >>> 10.10.10.91:6789/0 27 : [INF] mds0 10.10.10.93:6800/4702 up:reconnect >>> 2011-07-22 23:18:58.493288 pg v958: 594 pgs: 594 active+clean; 3760 >>> MB data, 13164 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:01.139243 pg v959: 594 pgs: 594 active+clean; 3760 >>> MB data, 13163 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:21.118647 osd e141: 3 osds: 3 up, 3 in >>> 2011-07-22 23:19:21.141306 pg v960: 594 pgs: 594 active+clean; 3760 >>> MB data, 13163 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:23.488866 pg v961: 594 pgs: 594 active+clean; 3760 >>> MB data, 13165 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:24.516985 pg v962: 594 pgs: 594 active+clean; 3760 >>> MB data, 13167 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:46.738637 mds e199: 1/1/1 up {0=ceph3=up:rejoin} >>> 2011-07-22 23:19:46.800581 log 2011-07-22 23:19:48.667174 mon0 >>> 10.10.10.91:6789/0 28 : [INF] mds0 10.10.10.93:6800/4702 up:rejoin >>> 2011-07-22 23:19:46.859582 mds e200: 1/1/1 up {0=ceph3=up:active} >>> 2011-07-22 23:19:47.814926 log 2011-07-22 23:19:48.787984 mon0 >>> 10.10.10.91:6789/0 29 : [INF] mds0 10.10.10.93:6800/4702 up:active >>> 2011-07-22 23:19:49.584346 pg v963: 594 pgs: 594 active+clean; 3761 >>> MB data, 13168 MB used, 18063 MB / 35997 MB avail >>> 2011-07-22 23:19:50.598374 pg v964: 594 pgs: 594 active+clean; 3761 >>> MB data, 13166 MB used, 18062 MB / 35997 MB avail >>> 2011-07-22 23:20:01.943931 mds e201: 1/1/1 up >>> {0=ceph3=up:active(laggy or crashed)} >>> -- >>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in >>> the body of a message to majordomo@xxxxxxxxxxxxxxx >>> More majordomo info at http://vger.kernel.org/majordomo-info.html >>> >>> >> > -- To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
