<div dir="ltr">Thank you for the response Ken. Will watch for this to be reproduced again.</div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, May 16, 2019 at 4:10 AM Ken Gaillot <<a href="mailto:kgaillot@redhat.com">kgaillot@redhat.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Resurrecting a really old thread in case anyone had similar questions.<br>
This arrived at a crazy busy time and got neglected.<br>
<br>
The "finalization timer" is a timeout in the DC election process. The<br>
value is the join-finalization-timeout cluster property (formerly crmd-<br>
finalization-timeout), which defaults to 30 minutes.<br>
<br>
The whole election process is undocumented and quite arcane. It would<br>
be nice to document it but that's a bigger project than there is time<br>
for at the moment.<br>
<br>
The controller (crmd) is implemented as a finite state machine, meaning<br>
various inputs move it from one state to another according to fixed<br>
rules. The finalization timer is started when the "finalize join" state<br>
is reached, and stopped whenever that state is left. This state is<br>
achieved once the (possibly newly elected) DC has received join<br>
requests from all nodes, and is left once the DC has sync'd the CIB to<br>
those nodes, ack'd their join requests, and received confirmations back<br>
from them.<br>
<br>
Obviously it's too late to look at this particular incident, but if it<br>
can be reliably reproduced, I can take a new look.<br>
<br>
On Sun, 2018-10-28 at 23:32 +0530, Prasad Nagaraj wrote:<br>
> Hi :<br>
> <br>
> I came across a strange situation in my cluster few days back. I was<br>
> trying to replace one of the nodes in my 3 node cluster and I removed<br>
> and added that node back following due process as per <br>
> <a href="https://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html/Pacemaker_Explained/_removing_a_corosync_node.html" rel="noreferrer" target="_blank">https://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html/Pacemaker_Explained/_removing_a_corosync_node.html</a><br>
> . Updated corosync.conf on all nodes and restarted corosync and<br>
> pacemaker on all the nodes. The cluster didnt elect a DC and also<br>
> didnt report any activities for almost 28 mins as seen from below<br>
> logs. Then I saw this message: <br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_timer_popped: Finalization Timer (I_ELECTION) just popped<br>
> (1800000ms)<br>
> after which I could see further activities happening including DC<br>
> election.<br>
> <br>
> I was not able to understand or identify any reasons for this<br>
> behavior and also there is absolutely no documentation on this<br>
> Finalization timer and what it means. Appreciate any help in terms of<br>
> explaining what exactly this timer means and what could be reasons<br>
> for this behavior. I have pasted a snippet of logs during the time<br>
> here. I do have more logs and also logs from other nodes that I can<br>
> share if required.<br>
> <br>
> Thanks in advance for the help!<br>
> Prasad<br>
> <br>
> <br>
> Oct 22 22:07:46 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> nodes: OK (rc=0, origin=vm46890219c5/crm_attribute/4,<br>
> version=0.100.0)<br>
> Oct 22 22:07:46 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Reading cluster configuration file<br>
> /var/lib/pacemaker/cib/cib.QC3Kay (digest:<br>
> /var/lib/pacemaker/cib/cib.c74mjr)<br>
> Oct 22 22:07:47 [76412] vm85c4465533 cib: info:<br>
> cib_file_backup: Archived previous version as<br>
> /var/lib/pacemaker/cib/cib-96.raw<br>
> Oct 22 22:07:47 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Wrote version 0.100.0 of the CIB to disk<br>
> (digest: 3ab4bffdc9c372985cfe50ad3100131d)<br>
> Oct 22 22:07:47 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Reading cluster configuration file<br>
> /var/lib/pacemaker/cib/cib.7NqOEy (digest:<br>
> /var/lib/pacemaker/cib/cib.gamHhs)<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: Diff: --- 0.100.0 2<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: Diff: +++ 0.101.0 (null)<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: + /cib: @epoch=101<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: ++ /cib/configuration/constraints: <br>
> <rsc_location id="ms_mysql_member453" rsc="ms_mysql" score="0"<br>
> node="vm46890219c5"/><br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_apply_diff operation for section<br>
> 'all': OK (rc=0, origin=local/cibadmin/2, version=0.101.0)<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_file_backup: Archived previous version as<br>
> /var/lib/pacemaker/cib/cib-97.raw<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Wrote version 0.101.0 of the CIB to disk<br>
> (digest: 7ffa91a8ca752581d4c1df13d287e467)<br>
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Reading cluster configuration file<br>
> /var/lib/pacemaker/cib/cib.JkMV2C (digest:<br>
> /var/lib/pacemaker/cib/cib.mLy23A)<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: Diff: --- 0.101.0 2<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: Diff: +++ 0.102.0 (null)<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: + /cib: @epoch=102<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_perform_op: + <br>
> /cib/configuration/resources/master[@id='ms_mysql']/meta_attributes[@<br>
> id='ms_mysql-meta_attributes']/nvpair[@id='ms_mysql-meta_attributes-<br>
> maintenance']: @value=false<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> resources: OK (rc=0, origin=local/crm_resource/6, version=0.102.0)<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_file_backup: Archived previous version as<br>
> /var/lib/pacemaker/cib/cib-98.raw<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Wrote version 0.102.0 of the CIB to disk<br>
> (digest: dd6263dc226d652721b09ec702e37742)<br>
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:<br>
> cib_file_write_with_digest: Reading cluster configuration file<br>
> /var/lib/pacemaker/cib/cib.DOunDE (digest:<br>
> /var/lib/pacemaker/cib/cib.MYBrjE)<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_timer_popped: Finalization Timer (I_ELECTION) just popped<br>
> (1800000ms)<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> do_state_transition: State transition S_FINALIZE_JOIN -> S_ELECTION [<br>
> input=I_ELECTION cause=C_TIMER_POPPED origin=crm_timer_popped ]<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> update_dc: Unset DC. Was vm85c4465533<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> election_complete: Election election-0 complete<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> election_timeout_popped: Election failed: Declaring ourselves the<br>
> winner<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: do_log: <br>
> FSA: Input I_ELECTION_DC from election_timeout_popped() received in<br>
> state S_ELECTION<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: notice:<br>
> do_state_transition: State transition S_ELECTION -> S_INTEGRATION [<br>
> input=I_ELECTION_DC cause=C_TIMER_POPPED<br>
> origin=election_timeout_popped ]<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> do_dc_takeover: Taking over DC status for this partition<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_master operation for section<br>
> 'all': OK (rc=0, origin=local/crmd/86, version=0.102.0)<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section cib:<br>
> OK (rc=0, origin=local/crmd/87, version=0.102.0)<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> crm_config: OK (rc=0, origin=local/crmd/89, version=0.102.0)<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> crm_config: OK (rc=0, origin=local/crmd/91, version=0.102.0)<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm46890219c5[218109612] - join-2 phase 4 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm85c4465533[83891884] - join-2 phase 4 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm2ad44008dc[251664044] - join-2 phase 3 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-2: Sending offer to vm46890219c5<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm46890219c5[218109612] - join-2 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-2: Sending offer to vm85c4465533<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm85c4465533[83891884] - join-2 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-2: Sending offer to vm2ad44008dc<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm2ad44008dc[251664044] - join-2 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> do_dc_join_offer_all: join-2: Waiting on 3 outstanding join<br>
> acks<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: warning: do_log: <br>
> FSA: Input I_ELECTION_DC from do_election_check() received in state<br>
> S_INTEGRATION<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm46890219c5[218109612] - join-3 phase 1 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm85c4465533[83891884] - join-3 phase 1 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: initialize_join: Node<br>
> vm2ad44008dc[251664044] - join-3 phase 1 -> 0<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-3: Sending offer to vm46890219c5<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm46890219c5[218109612] - join-3 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-3: Sending offer to vm85c4465533<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm85c4465533[83891884] - join-3 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> join_make_offer: join-3: Sending offer to vm2ad44008dc<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crm_update_peer_join: join_make_offer: Node<br>
> vm2ad44008dc[251664044] - join-3 phase 0 -> 1<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> do_dc_join_offer_all: join-3: Waiting on 3 outstanding join<br>
> acks<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> crm_config: OK (rc=0, origin=local/crmd/93, version=0.102.0)<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> plugin_handle_membership: Membership 52: quorum retained<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crmd_cs_dispatch: Setting expected votes to 3<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> plugin_handle_membership: Membership 52: quorum retained<br>
> Oct 22 22:35:14 [76412] vm85c4465533 cib: info:<br>
> cib_process_request: Completed cib_modify operation for section<br>
> crm_config: OK (rc=0, origin=local/crmd/96, version=0.102.0)<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> crmd_cs_dispatch: Setting expected votes to 3<br>
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:<br>
> update_dc: Set DC to vm85c4465533 (3.0.10)<br>
-- <br>
Ken Gaillot <<a href="mailto:kgaillot@redhat.com" target="_blank">kgaillot@redhat.com</a>><br>
<br>
_______________________________________________<br>
Manage your subscription:<br>
<a href="https://lists.clusterlabs.org/mailman/listinfo/users" rel="noreferrer" target="_blank">https://lists.clusterlabs.org/mailman/listinfo/users</a><br>
<br>
ClusterLabs home: <a href="https://www.clusterlabs.org/" rel="noreferrer" target="_blank">https://www.clusterlabs.org/</a><br>
</blockquote></div>