Project

General

Profile

Bug #805 ยป mds.srv-an56n.log

John Leach, 02/14/2011 02:12 PM

 
2011-02-14 21:01:36.094732 7f91cc303720 starting mds.srv-an56n at 0.0.0.0:6800/3444
2011-02-14 21:01:36.095633 7f91cc303720 -- 0.0.0.0:6800/3444 messenger.start: error creating directory: '/': error 17: File exists
2011-02-14 21:01:36.098402 7f91c9865700 mds-1.0 ms_handle_connect on 10.202.105.222:6789/0
2011-02-14 21:01:43.040533 7f91c9865700 mds-1.0 handle_mds_map standby
2011-02-14 21:01:43.095183 7f91c9865700 mds0.14 handle_mds_map i am now mds0.14
2011-02-14 21:01:43.095223 7f91c9865700 mds0.14 handle_mds_map state change up:standby --> up:replay
2011-02-14 21:01:43.095236 7f91c9865700 mds0.14 replay_start
2011-02-14 21:01:43.095250 7f91c9865700 mds0.14 recovery set is
2011-02-14 21:01:43.095259 7f91c9865700 mds0.14 need osdmap epoch 1501, have 1496
2011-02-14 21:01:43.095333 7f91c9865700 mds0.cache handle_mds_failure mds0 : recovery peers are
2011-02-14 21:01:43.106345 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:43.106407 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).fault first fault
2011-02-14 21:01:43.106901 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:43.107497 7f91c9865700 mds0.14 ms_handle_connect on 10.67.65.62:6800/31962
2011-02-14 21:01:43.107537 7f91c9865700 mds0.14 ms_handle_connect on 10.135.211.78:6801/12851
2011-02-14 21:01:43.107773 7f91c9865700 mds0.14 ms_handle_connect on 10.61.136.222:6800/24309
2011-02-14 21:01:43.309006 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:43.711085 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:44.513015 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:46.114763 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 0.0.0.0:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:46.985860 7f91c9865700 mds0.14 ms_handle_reset on 10.135.211.78:6801/12851
2011-02-14 21:01:46.986503 7f91c725b700 -- 10.202.105.222:6800/3444 >> 10.135.211.78:6801/12851 pipe(0x1d56280 sd=7 pgs=0 cs=0 l=0).fault with nothing to send, going to standby
2011-02-14 21:01:49.316665 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:54.020407 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=10 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:01:59.022823 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:02:04.023095 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=9 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:02:09.023504 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=7 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:02:14.025210 7f91c745d700 -- 10.202.105.222:6800/3444 >> 10.202.105.222:6801/24280 pipe(0x1d56500 sd=7 pgs=0 cs=0 l=0).connect claims to be 10.202.105.222:6801/3512 not 10.202.105.222:6801/24280 - wrong node!
2011-02-14 21:02:14.026899 7f91c9865700 mds0.14 ms_handle_connect on 10.135.211.78:6801/22875
2011-02-14 21:02:59.867133 7f91c9865700 mds0.cache creating system inode with ino:100
2011-02-14 21:02:59.867415 7f91c9865700 mds0.cache creating system inode with ino:1
2011-02-14 21:03:05.579551 7f91c7059700 mds0.journaler try_read_entry got 0 len entry at offset 4051698581
2011-02-14 21:03:05.579615 7f91c7059700 mds0.log _replay journaler got error -22, aborting
2011-02-14 21:03:05.582298 7f91c7059700 mds0.14 boot_start encountered an error, failing
2011-02-14 21:03:05.582323 7f91c7059700 mds0.14 suicide. wanted up:replay, now down:dne
2011-02-14 21:03:05.583656 7f91cc303720 stopped.
2011-02-14 22:10:27.345887 7fbc748ad720 starting mds.srv-an56n at 0.0.0.0:6800/4058
2011-02-14 22:10:27.346790 7fbc748ad720 -- 0.0.0.0:6800/4058 messenger.start: error creating directory: '/': error 17: File exists
2011-02-14 22:10:27.347403 7fbc748ad720 mds-1.0 168 MDSCacheObject
2011-02-14 22:10:27.347425 7fbc748ad720 mds-1.0 2192 CInode
2011-02-14 22:10:27.347433 7fbc748ad720 mds-1.0 16 elist<>::item *7=112
2011-02-14 22:10:27.347440 7fbc748ad720 mds-1.0 360 inode_t
2011-02-14 22:10:27.347447 7fbc748ad720 mds-1.0 56 nest_info_t
2011-02-14 22:10:27.347454 7fbc748ad720 mds-1.0 32 frag_info_t
2011-02-14 22:10:27.347461 7fbc748ad720 mds-1.0 40 SimpleLock *5=200
2011-02-14 22:10:27.347468 7fbc748ad720 mds-1.0 48 ScatterLock *3=144
2011-02-14 22:10:27.347475 7fbc748ad720 mds-1.0 472 CDentry
2011-02-14 22:10:27.347482 7fbc748ad720 mds-1.0 16 elist<>::item
2011-02-14 22:10:27.347489 7fbc748ad720 mds-1.0 40 SimpleLock
2011-02-14 22:10:27.347496 7fbc748ad720 mds-1.0 1560 CDir
2011-02-14 22:10:27.347503 7fbc748ad720 mds-1.0 16 elist<>::item *2=32
2011-02-14 22:10:27.347510 7fbc748ad720 mds-1.0 192 fnode_t
2011-02-14 22:10:27.347517 7fbc748ad720 mds-1.0 56 nest_info_t *2
2011-02-14 22:10:27.347524 7fbc748ad720 mds-1.0 32 frag_info_t *2
2011-02-14 22:10:27.347531 7fbc748ad720 mds-1.0 168 Capability
2011-02-14 22:10:27.347541 7fbc748ad720 mds-1.0 32 xlist<>::item *2=64
2011-02-14 22:10:27.361709 7fbc748ac700 mds-1.0 MDS::ms_get_authorizer type=mon
2011-02-14 22:10:27.362347 7fbc71e0f700 mds-1.0 ms_handle_connect on 10.135.211.78:6789/0
2011-02-14 22:10:27.387913 7fbc748ad720 mds-1.0 beacon_send up:boot seq 1 (currently up:boot)
2011-02-14 22:10:27.388119 7fbc748ad720 mds-1.0 open_logger
2011-02-14 22:10:27.390253 7fbc71e0f700 mds-1.0 handle_mds_map epoch 62 from mon0
2011-02-14 22:10:27.390346 7fbc71e0f700 mds-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object}
2011-02-14 22:10:27.390372 7fbc71e0f700 mds-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate objec}
2011-02-14 22:10:27.390399 7fbc71e0f700 mds-1.0 map says i am 10.202.105.222:6800/4058 mds-1 state down:dne
2011-02-14 22:10:27.390415 7fbc71e0f700 mds-1.0 not in map yet
2011-02-14 22:10:31.388544 7fbc70d0c700 mds-1.0 beacon_send up:boot seq 2 (currently down:dne)
2011-02-14 22:10:31.432320 7fbc71e0f700 mds-1.0 handle_mds_map epoch 63 from mon0
2011-02-14 22:10:31.432413 7fbc71e0f700 mds-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object}
2011-02-14 22:10:31.432436 7fbc71e0f700 mds-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate objec}
2011-02-14 22:10:31.432464 7fbc71e0f700 mds-1.0 map says i am 10.202.105.222:6800/4058 mds-1 state up:standby
2011-02-14 22:10:31.432482 7fbc71e0f700 mds-1.0 handle_mds_map standby
2011-02-14 22:10:31.466636 7fbc71e0f700 mds-1.0 handle_mds_map epoch 64 from mon0
2011-02-14 22:10:31.466683 7fbc71e0f700 mds-1.0 my compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object}
2011-02-14 22:10:31.466708 7fbc71e0f700 mds-1.0 mdsmap compat compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate objec}
2011-02-14 22:10:31.466723 7fbc71e0f700 mds0.0 map says i am 10.202.105.222:6800/4058 mds0 state up:replay
2011-02-14 22:10:31.466836 7fbc71e0f700 mds0.16 handle_mds_map i am now mds0.16
2011-02-14 22:10:31.466852 7fbc71e0f700 mds0.16 handle_mds_map state change up:standby --> up:replay
2011-02-14 22:10:31.466865 7fbc71e0f700 mds0.16 replay_start
2011-02-14 22:10:31.466882 7fbc71e0f700 mds0.cache set_recovery_set
2011-02-14 22:10:31.466891 7fbc71e0f700 mds0.16 recovery set is
2011-02-14 22:10:31.466900 7fbc71e0f700 mds0.16 need osdmap epoch 1788, have 1787
2011-02-14 22:10:31.466961 7fbc71e0f700 mds0.cache handle_mds_failure mds0
2011-02-14 22:10:31.466983 7fbc71e0f700 mds0.cache handle_mds_failure mds0 : recovery peers are
2011-02-14 22:10:31.466993 7fbc71e0f700 mds0.cache wants_resolve
2011-02-14 22:10:31.467001 7fbc71e0f700 mds0.cache got_resolve
2011-02-14 22:10:31.467008 7fbc71e0f700 mds0.cache rejoin_sent
2011-02-14 22:10:31.467015 7fbc71e0f700 mds0.cache rejoin_gather
2011-02-14 22:10:31.467022 7fbc71e0f700 mds0.cache rejoin_ack_gather
2011-02-14 22:10:31.467037 7fbc71e0f700 mds0.migrator handle_mds_failure_or_stop mds0
2011-02-14 22:10:31.467053 7fbc71e0f700 mds0.cache show_subtrees - no subtrees
2011-02-14 22:10:31.468142 7fbc71e0f700 mds0.16 boot_start 1: opening inotable
2011-02-14 22:10:31.468176 7fbc71e0f700 mds0.inotable: load
2011-02-14 22:10:31.468370 7fbc71e0f700 mds0.16 boot_start 1: opening sessionmap
2011-02-14 22:10:31.468436 7fbc71e0f700 mds0.sessionmap load
2011-02-14 22:10:31.468478 7fbc71e0f700 mds0.16 boot_start 1: opening anchor table
2011-02-14 22:10:31.468510 7fbc71e0f700 mds0.anchortable: load
2011-02-14 22:10:31.468657 7fbc71e0f700 mds0.16 boot_start 1: opening snap table
2011-02-14 22:10:31.468708 7fbc71e0f700 mds0.snaptable: load
2011-02-14 22:10:31.468904 7fbc71e0f700 mds0.16 boot_start 1: opening mds log
2011-02-14 22:10:31.468940 7fbc71e0f700 mds0.log open discovering log bounds
2011-02-14 22:10:31.468970 7fbc71e0f700 mds0.journaler recover start
2011-02-14 22:10:31.468983 7fbc71e0f700 mds0.journaler read_head
2011-02-14 22:10:31.470719 7fbc6fc09700 mds0.16 MDS::ms_get_authorizer type=osd
2011-02-14 22:10:31.473100 7fbc71e0f700 mds0.16 ms_handle_connect on 10.135.211.78:6801/22875
2011-02-14 22:10:31.482577 7fbc6fb08700 mds0.16 MDS::ms_get_authorizer type=osd
2011-02-14 22:10:31.501086 7fbc6fd0a700 mds0.16 MDS::ms_get_authorizer type=osd
2011-02-14 22:10:31.501393 7fbc71e0f700 mds0.16 ms_handle_connect on 10.61.136.222:6800/24309
2011-02-14 22:10:31.538380 7fbc71e0f700 mds0.16 ms_handle_connect on 10.67.65.62:6800/31962
2011-02-14 22:10:31.706717 7fbc71e0f700 mds0.inotable: load_2 got 29 bytes
2011-02-14 22:10:31.706778 7fbc71e0f700 mds0.inotable: load_2 loaded v926337
2011-02-14 22:10:31.715017 7fbc71e0f700 mds0.sessionmap dump
2011-02-14 22:10:31.715065 7fbc71e0f700 mds0.sessionmap _load_finish v 1852076, 1 sessions, 216 bytes
2011-02-14 22:10:31.715077 7fbc71e0f700 mds0.sessionmap dump
2011-02-14 22:10:31.715108 7fbc71e0f700 mds0.sessionmap client4105 0x292dd80 state open completed prealloc_inos [100000e2280~3e8] used_ions []
2011-02-14 22:10:31.855756 7fbc71e0f700 mds0.journaler _finish_read_head loghead(trim 4055891968, expire 4051698581, write 4183293723). probing for end of log (from 4183293723)...
2011-02-14 22:10:31.855789 7fbc71e0f700 mds0.journaler probing for end of the log
2011-02-14 22:10:31.862874 7fbc71e0f700 mds0.anchortable: load_2 got 29 bytes
2011-02-14 22:10:31.862902 7fbc71e0f700 mds0.anchortable: load_2 loaded v0
2011-02-14 22:10:32.388538 7fbc70d0c700 mds0.bal get_load no root, no load
2011-02-14 22:10:32.388943 7fbc70d0c700 mds0.bal get_load mdsload<[0,0 0]/[0,0 0], req 0, hr 0, qlen 0, cpu 0.04>
2011-02-14 22:10:32.474646 7fbc71e0f700 mds0.snaptable: load_2 got 41 bytes
2011-02-14 22:10:32.474712 7fbc71e0f700 mds0.snaptable: load_2 loaded v0
2011-02-14 22:10:32.475343 7fbc71e0f700 mds0.journaler _finish_probe_end write_pos = 4183294378 (header had 4183293723). recovered.
2011-02-14 22:10:32.475390 7fbc71e0f700 mds0.16 boot_start 2: loading/discovering base inodes
2011-02-14 22:10:32.475428 7fbc71e0f700 mds0.cache creating system inode with ino:100
2011-02-14 22:10:32.475540 7fbc71e0f700 mds0.cache.ino(100) fetch
2011-02-14 22:10:32.475703 7fbc71e0f700 mds0.cache creating system inode with ino:1
2011-02-14 22:10:32.475738 7fbc71e0f700 mds0.cache.ino(1) fetch
2011-02-14 22:10:32.536955 7fbc71e0f700 mds0.cache.ino(100) _fetched got 0 and 396
2011-02-14 22:10:32.536995 7fbc71e0f700 mds0.cache.ino(100) magic is 'ceph fs volume v011' (expecting 'ceph fs volume v011')
2011-02-14 22:10:32.537041 7fbc71e0f700 mds0.cache.ino(100) decode_snap_blob snaprealm(100 seq 1 lc 0 cr 0 cps 1 snaps={} 0x292d240)
2011-02-14 22:10:32.537114 7fbc71e0f700 mds0.cache.ino(100) _fetched [inode 100 [...2,head] ~mds0/ auth v3 snaprealm=0x292d240 f(v0 2=1+1) n(v2 rc2011-02-09 22:56:42.082085 b2463744 1005=1004+1)/n(v0 2=1+1) (iversion lock) 0x2935000]
2011-02-14 22:10:32.553912 7fbc71e0f700 mds0.cache.ino(1) _fetched got 0 and 425
2011-02-14 22:10:32.553950 7fbc71e0f700 mds0.cache.ino(1) magic is 'ceph fs volume v011' (expecting 'ceph fs volume v011')
2011-02-14 22:10:32.553977 7fbc71e0f700 mds0.cache.ino(1) decode_snap_blob snaprealm(1 seq 1 lc 0 cr 0 cps 1 snaps={} 0x292db40)
2011-02-14 22:10:32.554011 7fbc71e0f700 mds0.cache.ino(1) _fetched [inode 1 [...2,head] / auth v1 snaprealm=0x292db40 f(v0 1=0+1) n(v0 1=0+1) (iversion lock) 0x2935890]
2011-02-14 22:10:32.554024 7fbc71e0f700 mds0.16 boot_start 3: replaying mds log
2011-02-14 22:10:32.554034 7fbc71e0f700 mds0.log replay start, from 4051698581 to 4183294378
2011-02-14 22:10:32.554246 7fbc6f704700 mds0.log _replay_thread start
2011-02-14 22:10:32.554294 7fbc6f704700 mds0.journaler _issue_read reading only up to ack_pos 4183294378
2011-02-14 22:10:32.554316 7fbc6f704700 mds0.journaler _issue_read reading 4051698581~131595797, read pointers 4051698581/4051698581/4183294378
2011-02-14 22:10:32.556713 7fbc6f704700 mds0.journaler wait_for_readable at 4051698581 onreadable 0x28f6be0
2011-02-14 22:10:33.879652 7fbc71e0f700 mds0.journaler _finish_read got 4051698581~131595797
2011-02-14 22:10:33.879709 7fbc71e0f700 mds0.journaler _finish_read read_buf now 4051698581~131595797, read pointers 4051698581/4183294378/4183294378
2011-02-14 22:10:33.879721 7fbc71e0f700 mds0.journaler _finish_read now readable
2011-02-14 22:10:33.879826 7fbc6f704700 mds0.journaler try_read_entry at 4051698581 reading 4051698581~4 (have 131595797)
2011-02-14 22:10:33.879859 7fbc6f704700 mds0.journaler try_read_entry got 0 len entry at offset 4051698581
2011-02-14 22:10:33.879877 7fbc6f704700 mds0.log _replay journaler got error -22, aborting
2011-02-14 22:10:33.879896 7fbc6f704700 mds0.journaler reread_head
2011-02-14 22:10:33.883485 7fbc6f704700 mds0.log _replay_thread kicking waiters
2011-02-14 22:10:33.883537 7fbc6f704700 mds0.16 boot_start encountered an error, failing
2011-02-14 22:10:33.883558 7fbc6f704700 mds0.16 suicide. wanted up:replay, now down:dne
2011-02-14 22:10:33.883911 7fbc6f704700 mds0.log _replay_thread finish
2011-02-14 22:10:33.884890 7fbc748ad720 stopped.
    (1-1/1)