Hi Joao,
Thanks for your reply!
I captured the log after seeing the 'noin' keyword and the log is attached.
Meanwhile, while checking the monitor logs, I see it does election every few seconds and the election process could take several seconds, so that the cluster is doing election almost all the time (could that be the root cause that we see out of date cluster status and command failure?).
I captured one round of election logs and following is the log, please help to check. Thanks very much.
2014-01-23 04:01:08.871622 7fa5fbe21700 5 mon.osd152@0(leader).elector(204008) handle_propose from mon.1
2014-01-23 04:01:08.871625 7fa5fbe21700 5 mon.osd152@0(leader).elector(204008) got propose from old epoch, quorum is 0,2, mon.1 must have just started
2014-01-23 04:01:08.871627 7fa5fbe21700 10 mon.osd152@0(leader) e1 start_election
2014-01-23 04:01:08.871629 7fa5fbe21700 10 mon.osd152@0(electing) e1 _reset
2014-01-23 04:01:08.871635 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.871636 7fa5fbe21700 10 mon.osd152@0(electing) e1 timecheck_finish
2014-01-23 04:01:08.871640 7fa5fbe21700 10 mon.osd152@0(electing) e1 scrub_reset
2014-01-23 04:01:08.871642 7fa5fbe21700 10 mon.osd152@0(electing).paxos(paxos active c 4353345..4353903) restart -- canceling timeouts
2014-01-23 04:01:08.871646 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(pgmap 2388001..2388518) restart
2014-01-23 04:01:08.871649 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(mdsmap 1..1) restart
2014-01-23 04:01:08.871651 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(osdmap 133136..134893) restart
2014-01-23 04:01:08.871653 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) restart
2014-01-23 04:01:08.871654 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) canceling proposal_timer 0x47d3e40
2014-01-23 04:01:08.871657 7fa5fbe21700 7 mon.osd152@0(electing).log v1793958 _updated_log for mon.2 10.194.0.68:6789/0
2014-01-23 04:01:08.871663 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> 10.194.0.68:6789/0 -- route(log(last 39415) v1 tid 3682233) v2 -- ?+0 0x1236de80 con 0x301c8e0
2014-01-23 04:01:08.871677 7fa5fbe21700 7 mon.osd152@0(electing).log v1793958 _updated_log for mon.0 10.193.207.130:6789/0
2014-01-23 04:01:08.871681 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> 10.193.207.130:6789/0 -- log(last 192924) v1 -- ?+0 0x53ccec0 con 0x3018580
2014-01-23 04:01:08.871690 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(monmap 1..1) restart
2014-01-23 04:01:08.871693 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(auth 2010..2269) restart
2014-01-23 04:01:08.871696 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.871709 7fa5fbe21700 0 log [INF] : mon.osd152 calling new monitor election
2014-01-23 04:01:08.871732 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.0 10.193.207.130:6789/0 -- log(2 entries) v1 -- ?+0 0x408b33c0
2014-01-23 04:01:08.871739 7fa5fbe21700 5 mon.osd152@0(electing).elector(204008) start -- can i be leader?
2014-01-23 04:01:08.871834 7fa5fbe21700 1 mon.osd152@0(electing).elector(204008) init, last seen epoch 204008
2014-01-23 04:01:08.871836 7fa5fbe21700 10 mon.osd152@0(electing).elector(204008) bump_epoch 204008 to 204009
2014-01-23 04:01:08.872379 7fa5fbe21700 10 mon.osd152@0(electing) e1 join_election
2014-01-23 04:01:08.872389 7fa5fbe21700 10 mon.osd152@0(electing) e1 _reset
2014-01-23 04:01:08.872391 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.872392 7fa5fbe21700 10 mon.osd152@0(electing) e1 timecheck_finish
2014-01-23 04:01:08.872394 7fa5fbe21700 10 mon.osd152@0(electing) e1 scrub_reset
2014-01-23 04:01:08.872396 7fa5fbe21700 10 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) restart -- canceling timeouts
2014-01-23 04:01:08.872399 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(pgmap 2388001..2388518) restart
2014-01-23 04:01:08.872401 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(mdsmap 1..1) restart
2014-01-23 04:01:08.872403 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(osdmap 133136..134893) restart
2014-01-23 04:01:08.872404 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) restart
2014-01-23 04:01:08.872406 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(monmap 1..1) restart
2014-01-23 04:01:08.872407 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(auth 2010..2269) restart
2014-01-23 04:01:08.872415 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.1 10.193.207.131:6789/0 -- election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204009) v4 -- ?+0 0x2d611d40
2014-01-23 04:01:08.872434 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.2 10.194.0.68:6789/0 -- election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204009) v4 -- ?+0 0x41505c40
2014-01-23 04:01:08.872456 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.2 10.194.0.68:6789/0 463485294 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204009) v4 ==== 540+0+0 (3981094898 0 0) 0x2d610000 con 0x301c8e0
2014-01-23 04:01:08.872478 7fa5fbe21700 5 mon.osd152@0(electing).elector(204009) handle_propose from mon.2
2014-01-23 04:01:08.872485 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0x1236e540 con 0x3018580
2014-01-23 04:01:08.872495 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) dispatch log(2 entries) v1 from mon.0 10.193.207.130:6789/0
2014-01-23 04:01:08.872501 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872502 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872509 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) waiting for paxos -> readable (v0)
2014-01-23 04:01:08.872511 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872512 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872516 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.1 10.193.207.131:6789/0 398310803 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 ack 204007) v4 ==== 540+0+0 (382260333 0 0) 0x408b3600 con 0x301cba0
2014-01-23 04:01:08.872530 7fa5fbe21700 5 mon.osd152@0(electing).elector(204009) old epoch, dropping
2014-01-23 04:01:08.872534 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0x41504c80 con 0x3018580
2014-01-23 04:01:08.872539 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) dispatch log(2 entries) v1 from mon.0 10.193.207.130:6789/0
2014-01-23 04:01:08.872542 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872543 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872547 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) waiting for paxos -> readable (v0)
2014-01-23 04:01:08.872548 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872549 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872553 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.1 10.193.207.131:6789/0 398310804 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204009) v4 ==== 540+0+0 (3981094898 0 0) 0x408b7740 con 0x301cba0
2014-01-23 04:01:08.872565 7fa5fbe21700 5 mon.osd152@0(electing).elector(204009) handle_propose from mon.1
2014-01-23 04:01:08.872568 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(last 192924) v1 ==== 0+0+0 (0 0 0) 0x53ccec0 con 0x3018580
2014-01-23 04:01:08.872824 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0x408b33c0 con 0x3018580
2014-01-23 04:01:08.872830 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) dispatch log(2 entries) v1 from mon.0 10.193.207.130:6789/0
2014-01-23 04:01:08.872834 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872835 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872839 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) waiting for paxos -> readable (v0)
2014-01-23 04:01:08.872841 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.872841 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.872846 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== osd.448 10.194.0.143:6816/357 1 ==== auth(proto 0 28 bytes epoch 1) v1 ==== 58+0+0 (1794778480 0 0) 0x25398fc0 con 0x25347640
2014-01-23 04:01:08.872854 7fa5fbe21700 5 mon.osd152@0(electing) e1 discarding message auth(proto 0 28 bytes epoch 1) v1 and sending client elsewhere
2014-01-23 04:01:08.872857 7fa5fbe21700 1 -- 10.193.207.130:6789/0 mark_down 0x25347640 -- 0x21ee4380
2014-01-23 04:01:08.874236 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.2 10.194.0.68:6789/0 463485295 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204011) v4 ==== 540+0+0 (229380923 0 0) 0x1236de80 con 0x301c8e0
2014-01-23 04:01:08.874266 7fa5fbe21700 5 mon.osd152@0(electing).elector(204009) handle_propose from mon.2
2014-01-23 04:01:08.874270 7fa5fbe21700 10 mon.osd152@0(electing).elector(204009) bump_epoch 204009 to 204011
2014-01-23 04:01:08.874755 7fa5fbe21700 10 mon.osd152@0(electing) e1 join_election
2014-01-23 04:01:08.874764 7fa5fbe21700 10 mon.osd152@0(electing) e1 _reset
2014-01-23 04:01:08.874767 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.874768 7fa5fbe21700 10 mon.osd152@0(electing) e1 timecheck_finish
2014-01-23 04:01:08.874770 7fa5fbe21700 10 mon.osd152@0(electing) e1 scrub_reset
2014-01-23 04:01:08.874771 7fa5fbe21700 10 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) restart -- canceling timeouts
2014-01-23 04:01:08.874775 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(pgmap 2388001..2388518) restart
2014-01-23 04:01:08.874777 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(mdsmap 1..1) restart
2014-01-23 04:01:08.874779 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(osdmap 133136..134893) restart
2014-01-23 04:01:08.874780 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) restart
2014-01-23 04:01:08.874782 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(monmap 1..1) restart
2014-01-23 04:01:08.874783 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(auth 2010..2269) restart
2014-01-23 04:01:08.874786 7fa5fbe21700 10 mon.osd152@0(electing) e1 start_election
2014-01-23 04:01:08.874787 7fa5fbe21700 10 mon.osd152@0(electing) e1 _reset
2014-01-23 04:01:08.874788 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.874790 7fa5fbe21700 10 mon.osd152@0(electing) e1 timecheck_finish
2014-01-23 04:01:08.874791 7fa5fbe21700 10 mon.osd152@0(electing) e1 scrub_reset
2014-01-23 04:01:08.874793 7fa5fbe21700 10 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) restart -- canceling timeouts
2014-01-23 04:01:08.874795 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(pgmap 2388001..2388518) restart
2014-01-23 04:01:08.874797 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(mdsmap 1..1) restart
2014-01-23 04:01:08.874798 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(osdmap 133136..134893) restart
2014-01-23 04:01:08.874799 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) restart
2014-01-23 04:01:08.874800 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(monmap 1..1) restart
2014-01-23 04:01:08.874801 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(auth 2010..2269) restart
2014-01-23 04:01:08.874803 7fa5fbe21700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:08.874807 7fa5fbe21700 0 log [INF] : mon.osd152 calling new monitor election
2014-01-23 04:01:08.874824 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.0 10.193.207.130:6789/0 -- log(2 entries) v1 -- ?+0 0x408b7740
2014-01-23 04:01:08.874831 7fa5fbe21700 5 mon.osd152@0(electing).elector(204011) start -- can i be leader?
2014-01-23 04:01:08.874867 7fa5fbe21700 1 mon.osd152@0(electing).elector(204011) init, last seen epoch 204011
2014-01-23 04:01:08.874873 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.1 10.193.207.131:6789/0 -- election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204011) v4 -- ?+0 0x25398fc0
2014-01-23 04:01:08.874887 7fa5fbe21700 1 -- 10.193.207.130:6789/0 --> mon.2 10.194.0.68:6789/0 -- election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 propose 204011) v4 -- ?+0 0x408b4800
2014-01-23 04:01:08.874909 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.2 10.194.0.68:6789/0 463485296 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 ack 204011) v4 ==== 540+0+0 (1598534457 0 0) 0x2d6133c0 con 0x301c8e0
2014-01-23 04:01:08.874932 7fa5fbe21700 5 mon.osd152@0(electing).elector(204011) handle_ack from mon.2
2014-01-23 04:01:08.874936 7fa5fbe21700 5 mon.osd152@0(electing).elector(204011) so far i have {0=34359738367,2=34359738367}
2014-01-23 04:01:08.874943 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0x408b7740 con 0x3018580
2014-01-23 04:01:08.874959 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) dispatch log(2 entries) v1 from mon.0 10.193.207.130:6789/0
2014-01-23 04:01:08.874963 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.874964 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.874969 7fa5fbe21700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) waiting for paxos -> readable (v0)
2014-01-23 04:01:08.874971 7fa5fbe21700 1 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) is_readable now=2014-01-23 04:01:08.874971 lease_expire=2014-01-23 04:01:13.871236 has v0 lc 4353903
2014-01-23 04:01:08.875528 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.2 10.194.0.68:6789/0 463485297 ==== election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 ack 204011) v4 ==== 540+0+0 (1598534457 0 0) 0x2d613600 con 0x301c8e0
2014-01-23 04:01:08.875553 7fa5fbe21700 5 mon.osd152@0(electing).elector(204011) handle_ack from mon.2
2014-01-23 04:01:08.875556 7fa5fbe21700 5 mon.osd152@0(electing).elector(204011) so far i have {0=34359738367,2=34359738367}
2014-01-23 04:01:13.875028 7fa5fc822700 5 mon.osd152@0(electing).elector(204011) election timer expired
2014-01-23 04:01:13.875043 7fa5fc822700 10 mon.osd152@0(electing).elector(204011) bump_epoch 204011 to 204012
2014-01-23 04:01:13.875375 7fa5fc822700 10 mon.osd152@0(electing) e1 join_election
2014-01-23 04:01:13.875386 7fa5fc822700 10 mon.osd152@0(electing) e1 _reset
2014-01-23 04:01:13.875389 7fa5fc822700 10 mon.osd152@0(electing) e1 cancel_probe_timeout (none scheduled)
2014-01-23 04:01:13.875390 7fa5fc822700 10 mon.osd152@0(electing) e1 timecheck_finish
2014-01-23 04:01:13.875393 7fa5fc822700 10 mon.osd152@0(electing) e1 scrub_reset
2014-01-23 04:01:13.875395 7fa5fc822700 10 mon.osd152@0(electing).paxos(paxos recovering c 4353345..4353903) restart -- canceling timeouts
2014-01-23 04:01:13.875401 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(pgmap 2388001..2388518) restart
2014-01-23 04:01:13.875404 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(mdsmap 1..1) restart
2014-01-23 04:01:13.875407 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(osdmap 133136..134893) restart
2014-01-23 04:01:13.875409 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(logm 1793310..1793958) restart
2014-01-23 04:01:13.875411 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(monmap 1..1) restart
2014-01-23 04:01:13.875413 7fa5fc822700 10 mon.osd152@0(electing).paxosservice(auth 2010..2269) restart
2014-01-23 04:01:13.875423 7fa5fc822700 1 -- 10.193.207.130:6789/0 --> mon.2 10.194.0.68:6789/0 -- election(b9cb3ea9-e1de-48b4-9e86-6921e2c537d2 victory 204012) v4 -- ?+0 0x248bf980
2014-01-23 04:01:13.875445 7fa5fc822700 10 mon.osd152@0(electing) e1 win_election epoch 204012 quorum 0,2 features 34359738367
2014-01-23 04:01:13.875457 7fa5fc822700 0 log [INF] : mon.osd152@0 won leader election with quorum 0,2
2014-01-23 04:01:13.875481 7fa5fc822700 1 -- 10.193.207.130:6789/0 --> mon.0 10.193.207.130:6789/0 -- log(2 entries) v1 -- ?+0 0x248bc5c0
2014-01-23 04:01:13.875498 7fa5fc822700 10 mon.osd152@0(leader).paxos(paxos recovering c 4353345..4353903) leader_init -- starting paxos recovery
2014-01-23 04:01:13.875558 7fa5fbe21700 1 -- 10.193.207.130:6789/0 <== mon.0 10.193.207.130:6789/0 0 ==== log(2 entries) v1 ==== 0+0+0 (0 0 0) 0x248bc5c0 con 0x3018580
2014-01-23 04:01:13.875690 7fa5fc822700 10 mon.osd152@0(leader).paxos(paxos recovering c 4353345..4353903) get_new_proposal_number = 9772500
2014-01-23 04:01:13.875703 7fa5fc822700 10 mon.osd152@0(leader).paxos(paxos recovering c 4353345..4353903) collect with pn 9772500
2014-01-23 04:01:13.875708 7fa5fc822700 1 -- 10.193.207.130:6789/0 --> mon.2 10.194.0.68:6789/0 -- paxos(collect lc 4353903 fc 4353345 pn 9772500 opn 0) v3 -- ?+0 0x167ceb80
2014-01-23 04:01:13.875725 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(pgmap 2388001..2388518) election_finished
2014-01-23 04:01:13.875729 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(pgmap 2388001..2388518) _active - not active
2014-01-23 04:01:13.875731 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(mdsmap 1..1) election_finished
2014-01-23 04:01:13.875733 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(mdsmap 1..1) _active - not active
2014-01-23 04:01:13.875735 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(osdmap 133136..134893) election_finished
2014-01-23 04:01:13.875737 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(osdmap 133136..134893) _active - not active
2014-01-23 04:01:13.875740 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(logm 1793310..1793958) election_finished
2014-01-23 04:01:13.875741 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(logm 1793310..1793958) _active - not active
2014-01-23 04:01:13.875743 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(monmap 1..1) election_finished
2014-01-23 04:01:13.875745 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(monmap 1..1) _active - not active
2014-01-23 04:01:13.875747 7fa5fc822700 10 mon.osd152@0(leader).paxosservice(auth 2010..2269) election_finished
Attachment:
monitor_handle_command_partial_log.log
Description: Binary data
On Jan 22, 2014, at 9:14 PM, Joao Eduardo Luis <joao.luis@xxxxxxxxxxx> wrote:
> On 01/22/2014 11:34 AM, Guang wrote:
>> Thanks Sage.
>>
>> If we use the debug_mon and debug_paxos as 20, the log file is growing too fast, I set the log level as 10 and then: 1) run the 'ceph osd set noin' command, 2) grep the log with keyword 'noin', attached is the monitor log. Please help to check. Thanks very much!
>>
>>
>
>
> The log doesn't show the relevant part due to only containing log messages mentioning the 'noin' keyword.
>
> We need the portion of the log between a line containing
>
> '(leader).*handle_command mon_command({"prefix": "osd set", "key": "noin"}.*'
>
> and the first line (after that) containing 'won leader election'.
>
> Otherwise we are missing what is causing the election to be triggered.
>
> -Joao
>
>>
>>
>> Thanks,
>> Guang
>>
>> On Jan 21, 2014, at 12:35 AM, Sage Weil <sage@xxxxxxxxxxx> wrote:
>>
>>> On Sun, 19 Jan 2014, Guang wrote:
>>>> Thanks Sage.
>>>>
>>>> I just captured part of the log (it was fast growing), the process did
>>>> not hang but I saw the same pattern repeatedly. Should I increase the
>>>> log level and send over email (it constantly reproduced)?
>>>
>>> Sure! A representative fragment of the repeating fragment shoudl be
>>> enough.
>>>
>>> s
>>>>
>>>> Thanks,
>>>> Guang
>>>>
>>>> On Jan 18, 2014, at 12:05 AM, Sage Weil <sage@xxxxxxxxxxx> wrote:
>>>>
>>>>> On Fri, 17 Jan 2014, Guang wrote:
>>>>>> Thanks Sage.
>>>>>>
>>>>>> I further narrow down the problem to #any command using paxos service would hang#, following are details:
>>>>>>
>>>>>> 1. I am able to run ceph status / osd dump, etc., however, the result are out of date (though I stopped all OSDs, it does not reflect in ceph status report).
>>>>>>
>>>>>> -bash-4.1$ sudo ceph -s
>>>>>> cluster b9cb3ea9-e1de-48b4-9e86-6921e2c537d2
>>>>>> health HEALTH_WARN 2797 pgs degraded; 107 pgs down; 7503 pgs peering; 917 pgs recovering; 6079 pgs recovery_wait; 2957 pgs stale; 7771 pgs stuck inactive; 2957 pgs stuck stale; 16567 pgs stuck unclean; recovery 54346804/779462977 degraded (6.972%); 9/259724199 unfound (0.000%); 2 near full osd(s); 57/751 in osds are down; noout,nobackfill,norecover,noscrub,nodeep-scrub flag(s) set
>>>>>> monmap e1: 3 mons at {osd151=10.194.0.68:6789/0,osd152=10.193.207.130:6789/0,osd153=10.193.207.131:6789/0}, election epoch 123278, quorum 0,1,2 osd151,osd152,osd153
>>>>>> osdmap e134893: 781 osds: 694 up, 751 in
>>>>>> pgmap v2388518: 22203 pgs: 26 inactive, 14 active, 79 stale+active+recovering, 5020 active+clean, 242 stale, 4352 active+recovery_wait, 616 stale+active+clean, 177 active+recovering+degraded, 6714 peering, 925 stale+active+recovery_wait, 86 down+peering, 1547 active+degraded, 32 stale+active+recovering+degraded, 648 stale+peering, 21 stale+down+peering, 239 stale+active+degraded, 651 active+recovery_wait+degraded, 30 remapped+peering, 151 stale+active+recovery_wait+degraded, 4 stale+remapped+peering, 629 active+recovering; 79656 GB data, 363 TB used, 697 TB / 1061 TB avail; 54346804/779462977 degraded (6.972%); 9/259724199 unfound (0.000%)
>>>>>> mdsmap e1: 0/0/1 up
>>>>>>
>>>>>> 2. If I run a command which uses paxos, the command will hang forever, this includes, ceph osd set noup (and also including those commands osd send to monitor when being started (create-or-add)).
>>>>>>
>>>>>> I attached the corresponding monitor log (it is like a bug).
>>>>>
>>>>> I see the osd set command coming through, but it arrives while paxos is
>>>>> converging and the log seems to end before the mon would normally process
>>>>> te delayed messages. Is there a reason why the log fragment you attached
>>>>> ends there, or did the process hang or something?
>>>>>
>>>>> Thanks-
>>>>> sage
>>>>>
>>>>>> I
>>>>>>
>>>>>> On Jan 17, 2014, at 1:35 AM, Sage Weil <sage@xxxxxxxxxxx> wrote:
>>>>>>
>>>>>>> Hi Guang,
>>>>>>>
>>>>>>> On Thu, 16 Jan 2014, Guang wrote:
>>>>>>>> I still have bad the luck to figure out what is the problem making authentication failure, so in order to get the cluster back, I tried:
>>>>>>>> 1. stop all daemons (mon & osd)
>>>>>>>> 2. change the configuration to disable cephx
>>>>>>>> 3. start mon daemons (3 in total)
>>>>>>>> 4. start osd daemon one by one
>>>>>>>>
>>>>>>>> After finishing step 3, the cluster can be reachable ('ceph -s' give results):
>>>>>>>> -bash-4.1$ sudo ceph -s
>>>>>>>> cluster b9cb3ea9-e1de-48b4-9e86-6921e2c537d2
>>>>>>>> health HEALTH_WARN 2797 pgs degraded; 107 pgs down; 7503 pgs peering; 917 pgs recovering; 6079 pgs recovery_wait; 2957 pgs stale; 7771 pgs stuck inactive; 2957 pgs stuck stale; 16567 pgs stuck unclean; recovery 54346804/779462977 degraded (6.972%); 9/259724199 unfound (0.000%); 2 near full osd(s); 57/751 in osds are down; noout,nobackfill,norecover,noscrub,nodeep-scrub flag(s) set
>>>>>>>> monmap e1: 3 mons at {osd151=10.194.0.68:6789/0,osd152=10.193.207.130:6789/0,osd153=10.193.207.131:6789/0}, election epoch 106022, quorum 0,1,2 osd151,osd152,osd153
>>>>>>>> osdmap e134893: 781 osds: 694 up, 751 in
>>>>>>>> pgmap v2388518: 22203 pgs: 26 inactive, 14 active, 79 stale+active+recovering, 5020 active+clean, 242 stale, 4352 active+recovery_wait, 616 stale+active+clean, 177 active+recovering+degraded, 6714 peering, 925 stale+active+recovery_wait, 86 down+peering, 1547 active+degraded, 32 stale+active+recovering+degraded, 648 stale+peering, 21 stale+down+peering, 239 stale+active+degraded, 651 active+recovery_wait+degraded, 30 remapped+peering, 151 stale+active+recovery_wait+degraded, 4 stale+remapped+peering, 629 active+recovering; 79656 GB data, 363 TB used, 697 TB / 1061 TB avail; 54346804/779462977 degraded (6.972%); 9/259724199 unfound (0.000%)
>>>>>>>> mdsmap e1: 0/0/1 up
>>>>>>>> (at this point, all OSDs should be down).
>>>>>>>>
>>>>>>>> When I tried to start OSD daemon, the starting script got hang, and the process hang is:
>>>>>>>> root 80497 80496 0 08:18 pts/0 00:00:00 python /usr/bin/ceph --name=osd.22 --keyring=/var/lib/ceph/osd/ceph-22/keyring osd crush create-or-move -- 22 0.40 root=default host=osd173
>>>>>>>>
>>>>>>>> When I strace the starting script, I got the following traces (process 75873 is the above process), it failed with futex and then do a infinite loop:
>>>>>>>> select(0, NULL, NULL, NULL, {0, 16000}) = 0 (Timeout)
>>>>>>>> Any idea what might trigger this?
>>>>>>>
>>>>>>> It is hard to tell from the strace what is going on from this. Do you see
>>>>>>> that the OSDs are booting in ceph.log (or ceph -w output)? If not, I
>>>>>>> would look at the osd daemon log for clues. You may need to turn up
>>>>>>> debugging to see (ceph daemon osd.NNN config set debug_osd 20 to adjust
>>>>>>> the level on the running daemon).
>>>>>>>
>>>>>>> If they are booting, it is mostly a matter of letting it recover and come
>>>>>>> up. We have seen patterns where configuration or network issues have let
>>>>>>> the system bury itself under a series of osdmap updates. If you see that
>>>>>>> in the log when you turn up debugging, or see the osds going up and down
>>>>>>> when you try to bring the cluster up, that could be what is going on. A
>>>>>>> strategy that has worked there is to let all the osds catch up on their
>>>>>>> maps before trying to peer and join the cluster. To do that, 'ceph osd
>>>>>>> set noup' (which prevents the osds from joining), wait for the ceph-osd
>>>>>>> processes to stop chewing on maps (watch the cpu utilization in top), and
>>>>>>> once they are all ready 'ceph osd unset noup' and let them join and peer
>>>>>>> all at once.
>>>>>>>
>>>>>>> sage
>>>>>>>
>>>>>>>>
>>>>>>>> ======= STRACE (PARTIAL) ==========
>>>>>>>> [pid 75873] futex(0xf707a0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
>>>>>>>> [pid 75878] mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f5da6529000
>>>>>>>> [pid 75878] munmap(0x7f5da6529000, 28143616) = 0
>>>>>>>> [pid 75878] munmap(0x7f5dac000000, 38965248) = 0
>>>>>>>> [pid 75878] mprotect(0x7f5da8000000, 135168, PROT_READ|PROT_WRITE) = 0
>>>>>>>> [pid 75878] futex(0xf707a0, FUTEX_WAKE_PRIVATE, 1) = 1
>>>>>>>> [pid 75873] <... futex resumed> ) = 0
>>>>>>>> [pid 75873] futex(0xdd3cb0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
>>>>>>>> [pid 75878] futex(0xdd3cb0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
>>>>>>>> [pid 75873] <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
>>>>>>>> [pid 75878] <... futex resumed> ) = 0
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 1000} <unfinished ...>
>>>>>>>> [pid 75878] rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
>>>>>>>> [pid 75878] mmap(NULL, 10489856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f5dadb28000
>>>>>>>> [pid 75878] mprotect(0x7f5dadb28000, 4096, PROT_NONE) = 0
>>>>>>>> [ omit some entries?]
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 16000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 32000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>>>>>>>> [pid 75873] select(0, NULL, NULL, NULL, {0, 50000}) = 0 (Timeout)
>>>>>>>>
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Guang
>>>>>>>>
>>>>>>>> On Jan 15, 2014, at 5:54 AM, Guang <yguang11@xxxxxxxxxxx> wrote:
>>>>>>>>
>>>>>>>>> Thanks Sage.
>>>>>>>>>
>>>>>>>>> -bash-4.1$ sudo ceph --admin-daemon /var/run/ceph/ceph-mon.osd151.asok mon_status
>>>>>>>>> { "name": "osd151",
>>>>>>>>> "rank": 2,
>>>>>>>>> "state": "electing",
>>>>>>>>> "election_epoch": 85469,
>>>>>>>>> "quorum": [],
>>>>>>>>> "outside_quorum": [],
>>>>>>>>> "extra_probe_peers": [],
>>>>>>>>> "sync_provider": [],
>>>>>>>>> "monmap": { "epoch": 1,
>>>>>>>>> "fsid": "b9cb3ea9-e1de-48b4-9e86-6921e2c537d2",
>>>>>>>>> "modified": "0.000000",
>>>>>>>>> "created": "0.000000",
>>>>>>>>> "mons": [
>>>>>>>>> { "rank": 0,
>>>>>>>>> "name": "osd152",
>>>>>>>>> "addr": "10.193.207.130:6789\/0"},
>>>>>>>>> { "rank": 1,
>>>>>>>>> "name": "osd153",
>>>>>>>>> "addr": "10.193.207.131:6789\/0"},
>>>>>>>>> { "rank": 2,
>>>>>>>>> "name": "osd151",
>>>>>>>>> "addr": "10.194.0.68:6789\/0"}]}}
>>>>>>>>>
>>>>>>>>> And:
>>>>>>>>>
>>>>>>>>> -bash-4.1$ sudo ceph --admin-daemon /var/run/ceph/ceph-mon.osd151.asok quorum_status
>>>>>>>>> { "election_epoch": 85480,
>>>>>>>>> "quorum": [
>>>>>>>>> 0,
>>>>>>>>> 1,
>>>>>>>>> 2],
>>>>>>>>> "quorum_names": [
>>>>>>>>> "osd151",
>>>>>>>>> "osd152",
>>>>>>>>> "osd153"],
>>>>>>>>> "quorum_leader_name": "osd152",
>>>>>>>>> "monmap": { "epoch": 1,
>>>>>>>>> "fsid": "b9cb3ea9-e1de-48b4-9e86-6921e2c537d2",
>>>>>>>>> "modified": "0.000000",
>>>>>>>>> "created": "0.000000",
>>>>>>>>> "mons": [
>>>>>>>>> { "rank": 0,
>>>>>>>>> "name": "osd152",
>>>>>>>>> "addr": "10.193.207.130:6789\/0"},
>>>>>>>>> { "rank": 1,
>>>>>>>>> "name": "osd153",
>>>>>>>>> "addr": "10.193.207.131:6789\/0"},
>>>>>>>>> { "rank": 2,
>>>>>>>>> "name": "osd151",
>>>>>>>>> "addr": "10.194.0.68:6789\/0"}]}}
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> The election has been finished with leader selected from the above status.
>>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>> Guang
>>>>>>>>>
>>>>>>>>> On Jan 14, 2014, at 10:55 PM, Sage Weil <sage@xxxxxxxxxxx> wrote:
>>>>>>>>>
>>>>>>>>>> On Tue, 14 Jan 2014, GuangYang wrote:
>>>>>>>>>>> Hi ceph-users and ceph-devel,
>>>>>>>>>>> I came across an issue after restarting monitors of the cluster, that authentication fails which prevents running any ceph command.
>>>>>>>>>>>
>>>>>>>>>>> After we did some maintenance work, I restart OSD, however, I found that the OSD would not join the cluster automatically after being restarted, though TCP dump showed it had already sent messenger to monitor telling add me into the cluster.
>>>>>>>>>>>
>>>>>>>>>>> So that I suspected there might be some issues of monitor and I restarted monitor one by one (3 in total), however, after restarting monitors, all ceph command would fail saying authentication timeout?
>>>>>>>>>>>
>>>>>>>>>>> 2014-01-14 12:00:30.499397 7fc7f195e700 0 monclient(hunting): authenticate timed out after 300
>>>>>>>>>>> 2014-01-14 12:00:30.499440 7fc7f195e700 0 librados: client.admin authentication error (110) Connection timed out
>>>>>>>>>>> Error connecting to cluster: Error
>>>>>>>>>>>
>>>>>>>>>>> Any idea why such error happened (restarting OSD would result in the same error)?
>>>>>>>>>>>
>>>>>>>>>>> I am thinking the authentication information is persisted in mon local disk and is there a chance those data got corrupted?
>>>>>>>>>>
>>>>>>>>>> That sounds unlikely, but you're right that the core problem is with the
>>>>>>>>>> mons. What does
>>>>>>>>>>
>>>>>>>>>> ceph daemon mon.`hostname` mon_status
>>>>>>>>>>
>>>>>>>>>> say? Perhaps they are not forming a quorum and that is what is preventing
>>>>>>>>>> authentication.
>>>>>>>>>>
>>>>>>>>>> sage
>>>>>>>>>> --
>>>>>>>>>> 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
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>>
>>>
>>
>>
>>
>> _______________________________________________
>> ceph-users mailing list
>> ceph-users@xxxxxxxxxxxxxx
>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
>>
>
>
> --
> Joao Eduardo Luis
> Software Engineer | http://inktank.com | http://ceph.com
>
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
