<div dir="ltr">Hi - Any help on this will be very much appreciated.<div><br></div><div>Thanks!</div><div>Prasad</div></div><br><div class="gmail_quote"><div dir="ltr">On Sun, Oct 28, 2018 at 11:32 PM Prasad Nagaraj <<a href="mailto:prasad.nagaraj76@gmail.com">prasad.nagaraj76@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div>Hi :</div><div><br></div><div>I came across a strange situation in my cluster few days back. I was trying to replace one of the nodes in my 3 node cluster and I removed and added that node back following due process as per <a href="https://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html/Pacemaker_Explained/_removing_a_corosync_node.html" target="_blank">https://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html/Pacemaker_Explained/_removing_a_corosync_node.html</a>. Updated corosync.conf on all nodes and restarted corosync and pacemaker on all the nodes. The cluster didnt elect a DC and also didnt report any activities for almost 28 mins as seen from below logs. Then I saw this message: </div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_timer_popped: Finalization Timer (I_ELECTION) just popped (1800000ms)</div>after which I could see further activities happening including DC election.</div><div dir="ltr"><br></div><div dir="ltr">I was not able to understand or identify any reasons for this behavior and also there is absolutely no documentation on this Finalization timer and what it means. Appreciate any help in terms of explaining what exactly this timer means and what could be reasons for this behavior. I have pasted a snippet of logs during the time here. I do have more logs and also logs from other nodes that I can share if required.</div><div dir="ltr"><br></div><div dir="ltr">Thanks in advance for the help!</div><div dir="ltr">Prasad<br class="m_-4480533189471209562gmail-Apple-interchange-newline"><div><br></div><div><br></div><div>Oct 22 22:07:46 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section nodes: OK (rc=0, origin=vm46890219c5/crm_attribute/4, version=0.100.0)</div><div>Oct 22 22:07:46 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.QC3Kay (digest: /var/lib/pacemaker/cib/cib.c74mjr)</div><div>Oct 22 22:07:47 [76412] vm85c4465533 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-96.raw</div><div>Oct 22 22:07:47 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Wrote version 0.100.0 of the CIB to disk (digest: 3ab4bffdc9c372985cfe50ad3100131d)</div><div>Oct 22 22:07:47 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.7NqOEy (digest: /var/lib/pacemaker/cib/cib.gamHhs)</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_perform_op: Diff: --- 0.100.0 2</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_perform_op: Diff: +++ 0.101.0 (null)</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_perform_op: + /cib: @epoch=101</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_perform_op: ++ /cib/configuration/constraints: <rsc_location id="ms_mysql_member453" rsc="ms_mysql" score="0" node="vm46890219c5"/></div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_apply_diff operation for section 'all': OK (rc=0, origin=local/cibadmin/2, version=0.101.0)</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-97.raw</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Wrote version 0.101.0 of the CIB to disk (digest: 7ffa91a8ca752581d4c1df13d287e467)</div><div>Oct 22 22:07:48 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.JkMV2C (digest: /var/lib/pacemaker/cib/cib.mLy23A)</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_perform_op: Diff: --- 0.101.0 2</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_perform_op: Diff: +++ 0.102.0 (null)</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_perform_op: + /cib: @epoch=102</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_perform_op: + /cib/configuration/resources/master[@id='ms_mysql']/meta_attributes[@id='ms_mysql-meta_attributes']/nvpair[@id='ms_mysql-meta_attributes-maintenance']: @value=false</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section resources: OK (rc=0, origin=local/crm_resource/6, version=0.102.0)</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_file_backup: Archived previous version as /var/lib/pacemaker/cib/cib-98.raw</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Wrote version 0.102.0 of the CIB to disk (digest: dd6263dc226d652721b09ec702e37742)</div><div>Oct 22 22:07:49 [76412] vm85c4465533 cib: info: cib_file_write_with_digest: Reading cluster configuration file /var/lib/pacemaker/cib/cib.DOunDE (digest: /var/lib/pacemaker/cib/cib.MYBrjE)</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_timer_popped: Finalization Timer (I_ELECTION) just popped (1800000ms)</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_state_transition: State transition S_FINALIZE_JOIN -> S_ELECTION [ input=I_ELECTION cause=C_TIMER_POPPED origin=crm_timer_popped ]</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: update_dc: Unset DC. Was vm85c4465533</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: election_complete: Election election-0 complete</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: election_timeout_popped: Election failed: Declaring ourselves the winner</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_log: FSA: Input I_ELECTION_DC from election_timeout_popped() received in state S_ELECTION</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: notice: do_state_transition: State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC cause=C_TIMER_POPPED origin=election_timeout_popped ]</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_dc_takeover: Taking over DC status for this partition</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_master operation for section 'all': OK (rc=0, origin=local/crmd/86, version=0.102.0)</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section cib: OK (rc=0, origin=local/crmd/87, version=0.102.0)</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section crm_config: OK (rc=0, origin=local/crmd/89, version=0.102.0)</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section crm_config: OK (rc=0, origin=local/crmd/91, version=0.102.0)</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm46890219c5[218109612] - join-2 phase 4 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm85c4465533[83891884] - join-2 phase 4 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm2ad44008dc[251664044] - join-2 phase 3 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-2: Sending offer to vm46890219c5</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm46890219c5[218109612] - join-2 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-2: Sending offer to vm85c4465533</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm85c4465533[83891884] - join-2 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-2: Sending offer to vm2ad44008dc</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm2ad44008dc[251664044] - join-2 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_dc_join_offer_all: join-2: Waiting on 3 outstanding join acks</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: warning: do_log: FSA: Input I_ELECTION_DC from do_election_check() received in state S_INTEGRATION</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm46890219c5[218109612] - join-3 phase 1 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm85c4465533[83891884] - join-3 phase 1 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: initialize_join: Node vm2ad44008dc[251664044] - join-3 phase 1 -> 0</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-3: Sending offer to vm46890219c5</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm46890219c5[218109612] - join-3 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-3: Sending offer to vm85c4465533</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm85c4465533[83891884] - join-3 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: join_make_offer: join-3: Sending offer to vm2ad44008dc</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crm_update_peer_join: join_make_offer: Node vm2ad44008dc[251664044] - join-3 phase 0 -> 1</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_dc_join_offer_all: join-3: Waiting on 3 outstanding join acks</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section crm_config: OK (rc=0, origin=local/crmd/93, version=0.102.0)</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: plugin_handle_membership: Membership 52: quorum retained</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crmd_cs_dispatch: Setting expected votes to 3</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: plugin_handle_membership: Membership 52: quorum retained</div><div>Oct 22 22:35:14 [76412] vm85c4465533 cib: info: cib_process_request: Completed cib_modify operation for section crm_config: OK (rc=0, origin=local/crmd/96, version=0.102.0)</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: crmd_cs_dispatch: Setting expected votes to 3</div><div>Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: update_dc: Set DC to vm85c4465533 (3.0.10)</div><div><br></div></div></div></div>
</blockquote></div>