[ClusterLabs] Pacemaker startup retries

Ken Gaillot kgaillot at redhat.com
Wed Sep 5 10:17:44 EDT 2018


On Wed, 2018-09-05 at 13:31 +0200, Cesar Hernandez wrote:
> Hi
> 
> > 
> > The first fencing is legitimate -- the node hasn't been seen at
> > start-
> > up, and so needs to be fenced. The second fencing will be the one
> > of
> > interest. Also, look for the result of the first fencing.
> 
> The first fencing has finished with OK, as well as the other two
> fencing operations.
> 
> Aug 31 10:59:31 [30612] node1 stonith-ng:   notice:
> log_operation:     Operation 'reboot' [31075] (call 2 from
> crmd.30616) for host 'node2' with device 'st-fence_propio:0'
> returned: 0 (OK)
> 
> And the next log entries are:
> 
> Aug 31 10:59:31 [30612] node1 stonith-ng:   notice:
> remote_op_done:    Operation reboot of node2 by node1 for crmd.30616@
> node1.2d7857e7: OK
> Aug 31 10:59:31 [30616] node1       crmd:   notice:
> tengine_stonith_callback:  Stonith operation 2/81:0:0:c64efa2b-9366-
> 4c07-b5f1-6a2dbee79fe7: OK (0)
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> crm_get_peer:      Created entry 48db3347-5bbe-4cd4-b7ba-
> db4c697c3146/0x55adbeb587f0 for node node2/0 (2 total)
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> peer_update_callback:      node2 is now in unknown state
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> crm_get_peer:      Node 0 has uuid node2
> Aug 31 10:59:31 [30616] node1       crmd:   notice:
> crm_update_peer_state_iter:        crmd_peer_down: Node node2[0] -
> state is now lost (was (null))
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> peer_update_callback:      node2 is now lost (was in unknown state)
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> crm_update_peer_proc:      crmd_peer_down: Node node2[0] - all
> processes are now offline
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> peer_update_callback:      Client node2/peer now has status [offline]
> (DC=true, changed=     1)
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> crm_update_peer_expected:  crmd_peer_down: Node node2[0] - expected
> state is now down (was (null))
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> erase_status_tag:  Deleting xpath: //node_state[@uname='node2']/lrm
> Aug 31 10:59:31 [30616] node1       crmd:     info:
> erase_status_tag:  Deleting xpath:
> //node_state[@uname='node2']/transient_attributes
> Aug 31 10:59:31 [30616] node1       crmd:   notice:
> tengine_stonith_notify:    Peer node2 was terminated (reboot) by
> node1 for node1: OK (ref=2d7857e7-7e88-482a-812f-b343218974dc) by
> client crmd.30616
> 
> After some other entries I see:
> 
> Aug 31 10:59:37 [30615] node1    pengine:  warning:
> pe_fence_node:     Node node2 will be fenced because the peer has not
> been seen by the cluster

Ah, this rings a bell. Despite having fenced the node, the cluster
still considers the node unseen. That was a regression in 1.1.14 that
was fixed in 1.1.15. :-(

> Aug 31 10:59:37 [30615] node1    pengine:  warning:
> determine_online_status:   Node node2 is unclean
> 
> The server lasts aprox 2 minutes to reboot, so it's normal to haven't
> been seen after just 6 seconds. But I don't know why the server is
> rebooted three times:
> 
> Aug 31 10:59:31 [30616] node1       crmd:   notice:
> tengine_stonith_notify:	Peer node2 was terminated (reboot) by
> node1 for node1: OK (ref=2d7857e7-7e88-482a-812f-b343218974dc) by
> client crmd.30616
> ....
> Aug 31 10:59:53 [30616] node1       crmd:   notice:
> tengine_stonith_notify:	Peer node2 was terminated (reboot) by
> node1 for node1: OK (ref=2835cb08-362d-4d39-9133-3a7dcefb913c) by
> client crmd.30616
> ....
> Aug 31 11:00:05 [30616] node1       crmd:   notice:
> tengine_stonith_notify:	Peer node2 was terminated (reboot) by
> node1 for node1: OK (ref=17931f5b-76ea-4e3a-a792-535cea50afca) by
> client crmd.30616
> 
> 
> After the last message, I only see it stops fencing and start
> resources:
> 
> 
> Aug 31 11:00:05 [30616] node1       crmd:   notice:
> tengine_stonith_notify:    Peer node2 was terminated (reboot) by
> node1 for node1: OK (ref=17931f5b-76ea-4e3a-a792-535cea50afca) by
> client crmd.30616
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_modify operation for section
> status: OK (rc=0, origin=local/crmd/68, version=0.60.30)
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> erase_status_tag:  Deleting xpath: //node_state[@uname='node2']/lrm
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> erase_status_tag:  Deleting xpath:
> //node_state[@uname='node2']/transient_attributes
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> cib_fencing_updated:       Fencing update 68 for node2: complete
> Aug 31 11:00:05 [30616] node1       crmd:   notice:
> te_rsc_command:    Initiating action 66: start p_fs_database_start_0
> on node1 (local)
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> do_lrm_rsc_op:     Performing key=66:2:0:c64efa2b-9366-4c07-b5f1-
> 6a2dbee79fe7 op=p_fs_database_start_0
> Aug 31 11:00:05 [30613] node1       lrmd:     info:
> log_execute:       executing - rsc:p_fs_database action:start
> call_id:70
> Aug 31 11:00:05 [30616] node1       crmd:   notice:
> te_rsc_command:    Initiating action 77: start p_fs_datosweb_start_0
> on node1 (local)
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> do_lrm_rsc_op:     Performing key=77:2:0:c64efa2b-9366-4c07-b5f1-
> 6a2dbee79fe7 op=p_fs_datosweb_start_0
> Aug 31 11:00:05 [30613] node1       lrmd:     info:
> log_execute:       executing - rsc:p_fs_datosweb action:start
> call_id:71
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_delete operation for section
> //node_state[@uname='node2']/lrm: OK (rc=0, origin=local/crmd/69,
> version=0.60.30)
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_delete operation for section
> //node_state[@uname='node2']/transient_attributes: OK (rc=0,
> origin=local/crmd/70, version=0.60.30)
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_modify operation for section
> status: OK (rc=0, origin=local/crmd/71, version=0.60.30)
> Aug 31 11:00:05 [30616] node1       crmd:     info:
> cib_fencing_updated:       Fencing update 71 for node2: complete
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_delete operation for section
> //node_state[@uname='node2']/lrm: OK (rc=0, origin=local/crmd/72,
> version=0.60.30)
> Aug 31 11:00:05 [30611] node1        cib:     info:
> cib_process_request:       Completed cib_delete operation for section
> //node_state[@uname='node2']/transient_attributes: OK (rc=0,
> origin=local/crmd/73, version=0.60.30)
> Filesystem(p_fs_datosweb)[962]: 2018/08/31_11:00:05 INFO: Running
> start for /dev/drbd/by-res/datoswebstorage on /mnt/datosweb
> Filesystem(p_fs_database)[961]: 2018/08/31_11:00:05 INFO: Running
> start for /dev/drbd/by-res/databasestorage on /mnt/database
> 
> 
> ......
> 
> 
> Can you give me more clues?
> 
> Thanks a lot
> 
> Cesar
> 
> _______________________________________________
> Users mailing list: Users at clusterlabs.org
> https://lists.clusterlabs.org/mailman/listinfo/users
> 
> Project Home: http://www.clusterlabs.org
> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.
> pdf
> Bugs: http://bugs.clusterlabs.org
-- 
Ken Gaillot <kgaillot at redhat.com>



More information about the Users mailing list