[ClusterLabs] Regarding Finalization Timer (I_ELECTION) just popped (1800000ms)
Prasad Nagaraj
prasad.nagaraj76 at gmail.com
Tue Oct 30 06:55:06 EDT 2018
Hi - Any help on this will be very much appreciated.
Thanks!
Prasad
On Sun, Oct 28, 2018 at 11:32 PM Prasad Nagaraj <prasad.nagaraj76 at gmail.com>
wrote:
> Hi :
>
> 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
> https://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html/Pacemaker_Explained/_removing_a_corosync_node.html.
> 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:
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_timer_popped: Finalization Timer (I_ELECTION) just popped (1800000ms)
> after which I could see further activities happening including DC election.
>
> 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.
>
> Thanks in advance for the help!
> Prasad
>
>
> 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)
> 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)
> Oct 22 22:07:47 [76412] vm85c4465533 cib: info:
> cib_file_backup: Archived previous version as
> /var/lib/pacemaker/cib/cib-96.raw
> 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)
> 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)
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:
> cib_perform_op: Diff: --- 0.100.0 2
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:
> cib_perform_op: Diff: +++ 0.101.0 (null)
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:
> cib_perform_op: + /cib: @epoch=101
> 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"/>
> 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)
> Oct 22 22:07:48 [76412] vm85c4465533 cib: info:
> cib_file_backup: Archived previous version as
> /var/lib/pacemaker/cib/cib-97.raw
> 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)
> 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)
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:
> cib_perform_op: Diff: --- 0.101.0 2
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:
> cib_perform_op: Diff: +++ 0.102.0 (null)
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:
> cib_perform_op: + /cib: @epoch=102
> 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
> 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)
> Oct 22 22:07:49 [76412] vm85c4465533 cib: info:
> cib_file_backup: Archived previous version as
> /var/lib/pacemaker/cib/cib-98.raw
> 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)
> 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)
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_timer_popped: Finalization Timer (I_ELECTION) just popped (1800000ms)
> 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 ]
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: update_dc:
> Unset DC. Was vm85c4465533
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> election_complete: Election election-0 complete
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> election_timeout_popped: Election failed: Declaring ourselves the winner
> 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
> 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 ]
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> do_dc_takeover: Taking over DC status for this partition
> 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)
> 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)
> 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)
> 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)
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm46890219c5[218109612]
> - join-2 phase 4 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm85c4465533[83891884] -
> join-2 phase 4 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm2ad44008dc[251664044]
> - join-2 phase 3 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-2: Sending offer to vm46890219c5
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm46890219c5[218109612]
> - join-2 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-2: Sending offer to vm85c4465533
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm85c4465533[83891884] -
> join-2 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-2: Sending offer to vm2ad44008dc
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm2ad44008dc[251664044]
> - join-2 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> do_dc_join_offer_all: join-2: Waiting on 3 outstanding join acks
> 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
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm46890219c5[218109612]
> - join-3 phase 1 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm85c4465533[83891884] -
> join-3 phase 1 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: initialize_join: Node vm2ad44008dc[251664044]
> - join-3 phase 1 -> 0
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-3: Sending offer to vm46890219c5
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm46890219c5[218109612]
> - join-3 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-3: Sending offer to vm85c4465533
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm85c4465533[83891884] -
> join-3 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> join_make_offer: join-3: Sending offer to vm2ad44008dc
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crm_update_peer_join: join_make_offer: Node vm2ad44008dc[251664044]
> - join-3 phase 0 -> 1
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> do_dc_join_offer_all: join-3: Waiting on 3 outstanding join acks
> 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)
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> plugin_handle_membership: Membership 52: quorum retained
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crmd_cs_dispatch: Setting expected votes to 3
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> plugin_handle_membership: Membership 52: quorum retained
> 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)
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info:
> crmd_cs_dispatch: Setting expected votes to 3
> Oct 22 22:35:14 [76417] vm85c4465533 crmd: info: update_dc:
> Set DC to vm85c4465533 (3.0.10)
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clusterlabs.org/pipermail/users/attachments/20181030/dd27ca8d/attachment-0002.html>
More information about the Users
mailing list