[ClusterLabs] BUG in crmd/ccm membership handling when crmd registers with cluster a bit late
abort_transition_graph: do_te_invoke:158 - Triggered transition abort (complete=1) : Peer Halt Nov 26 19:07:12 node2 crmd[3523]: crit: s_crmd_fsa: Processing I_PE_CALC: [ state=S_INTEGRATION cause=C_FSA_INTERNAL origin=abort_transition_graph ] later crmd on the node that is coming up connects to heartbeat Nov 26 19:07:15 node1 crmd[2969]: notice: crm_cluster_connect: Connecting to cluster infrastructure: heartbeat Nov 26 19:07:15 node1 crmd[2969]:debug: register_heartbeat_conn: Signing in with Heartbeat Nov 26 19:07:15 node1 crmd[2969]: info: crm_get_peer: Created entry 75b26770-ac15-461c-889d-190e6c8139ac/0x7f2fd194f870 for node node1/0 (1 total) Nov 26 19:07:15 node1 crmd[2969]: crit: peer_update_callback: node1 is now (null) Nov 26 19:07:15 node1 crmd[2969]: info: crm_get_peer: Node 0 has uuid 0432-0432--2b91- Nov 26 19:07:15 node1 crmd[2969]: info: register_heartbeat_conn: Hostname: node1 Nov 26 19:07:15 node1 crmd[2969]: info: register_heartbeat_conn: UUID: 0432-0432--2b91- & at this point heartbeat delivers a notification into crmd as part of which crmd wrongly moves the status of the incoming node as offline/removing out of membership Nov 26 19:07:15 node2 crmd[3523]: notice: crmd_client_status_callback: Status update: Client node1/crmd now has status [join] (DC=true) Nov 26 19:07:15 node2 crmd[3523]: info: crm_update_peer_proc: crmd_client_status_callback: Node node1[0] - crmd is now join Nov 26 19:07:15 node2 crmd[3523]: crit: peer_update_callback: Client node1/peer now has status [offline] (DC=true) Nov 26 19:07:15 node2 crmd[3523]: warning: match_down_event: No match for shutdown action on 0432-0432--2b91- Nov 26 19:07:15 node2 crmd[3523]: crit: peer_update_callback: Alive=0, appear=0, down=(nil) Nov 26 19:07:15 node2 crmd[3523]: notice: peer_update_callback: Stonith/shutdown of node1 not matched Nov 26 19:07:15 node2 crmd[3523]: info: crm_update_peer_join: peer_update_callback: Node node1[0] - join-1 phase 1 -> 0 Nov 26 19:07:15 node2 crmd[3523]:debug: check_join_state: Invoked by peer_update_callback in state: S_INTEGRATION Nov 26 19:07:15 node2 crmd[3523]:debug: check_join_state: join-1: Integration of 0 peers complete: peer_update_callback Nov 26 19:07:15 node2 crmd[3523]: info: abort_transition_graph: peer_update_callback:214 - Triggered transition abort (complete=1) : Node failure so bottom-line due to a timing issue when crmd connects into hearbeat cluster we wrongly marked in the DC that the incoming node is not a member. this causes any message from incoming node from this point onwards to be ignored like Nov 26 19:07:18 node2 crmd[3523]:debug: crmd_ha_msg_callback: Ignoring HA message (op=noop) from node1: not in our membership list (size=1) Nov 26 19:07:19 node2 crmd[3523]: warning: crmd_ha_msg_callback: Ignoring HA message (op=join_announce) from node1: not in our membership list (size=1) --Shyam On Mon, Nov 23, 2015 at 9:30 PM, Shyam <shyam.kaus...@gmail.com> wrote: > One note on this. > > This problem doesnt happen if > > Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: > Status update: Client node2/crmd now has status [join] (DC=true) > Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: > Status update: Client node2/crmd now has status [leave] (DC=true) > Nov 19 08:36:31 node1 crmd[3298]: notice: crmd_client_status_callback: > Status update: Client node2/crmd now has status [join] (DC=true) > > join happens before > Nov 19 08:36:34 node1 crmd[3298]: notice: do_state_transition: State > transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN cause=C_FSA_INTERNAL > origin=peer_update_callback ] > > I am not sure why crmd join/leave & then join happens. With previous > version of heartbeat/pacemaker this doesnt happen. > > here are more logs when the problem doesnt happen > > Nov 19 08:36:29 node1 heartbeat: [3143]: info: Link node2:eth0 up. > Nov 19 08:36:29 node1 heartbeat: [3143]: info: Status update for node > node2: status init > Nov 19 08:36:29 node1 crmd[3298]: notice: crmd_ha_status_callback: > Status update: Node node2 now has status [init] > Nov 19 08:36:29 node1 crmd[3298]: notice: crmd_ha_status_callback: > Status update: Node node2 now has status [up] > Nov 19 08:36:30 node1 heartbeat: [3143]: debug: get_delnodelist: > delnodelist= > Nov 19 08:36:30 node1 heartbeat: [3143]: info: Status update for node > node2: status active > Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_ha_status_callback: > Status update: Node node2 now has status [active] > Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: > Status update: Client node2/crmd now has status [join] (DC=true) > Nov 19 08:36:30 node1 crmd[3298]: notice: crmd_client_status_callback: &
[ClusterLabs] heartbeat/pacemaker: running without DC when having a split-brain like situation due to linux crash
17:29:31 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_sync for section 'all' (origin=local/crmd/63, version=1.30.175): ok (rc=0) Nov 9 17:29:31 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_modify for section nodes (origin=local/crmd/64, version=1.30.176): ok (rc=0) Nov 9 17:29:31 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_modify for section nodes (origin=local/crmd/65, version=1.30.177): ok (rc=0) Nov 9 17:29:32 vm-1 lrmd: [2475]: info: stonith_api_device_metadata: looking up external/vmstonith/heartbeat metadata Nov 9 17:29:32 vm-1 vmstonith: Invoked as: /usr/lib/stonith/plugins/external/vmstonith getinfo-devdescr Nov 9 17:29:32 vm-1 vmstonith: Invoked as: /usr/lib/stonith/plugins/external/vmstonith getinfo-devid Nov 9 17:29:32 vm-1 vmstonith: Invoked as: /usr/lib/stonith/plugins/external/vmstonith getinfo-xml Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_dc_join_ack: join-2: Updating node state to member for vm-0 Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_dc_join_ack: join-2: Updating node state to member for vm-1 Nov 9 17:29:32 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_delete for section //node_state[@uname='vm-0']/transient_attributes (origin=vm-0/crmd/8, version=1.30.178): ok (rc=0) Nov 9 17:29:32 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_delete for section //node_state[@uname='vm-0']/lrm (origin=local/crmd/66, version=1.30.179): ok (rc=0) Nov 9 17:29:32 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_delete for section //node_state[@uname='vm-1']/lrm (origin=local/crmd/68, version=1.30.181): ok (rc=0) Nov 9 17:29:32 vm-1 crmd: [2478]: info: erase_xpath_callback: Deletion of "//node_state[@uname='vm-0']/lrm": ok (rc=0) Nov 9 17:29:32 vm-1 crmd: [2478]: info: erase_xpath_callback: Deletion of "//node_state[@uname='vm-1']/lrm": ok (rc=0) Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ] Nov 9 17:29:32 vm-1 crmd: [2478]: info: populate_cib_nodes_ha: Requesting the list of configured nodes Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_state_transition: All 2 cluster nodes are eligible to run resources. Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_dc_join_final: Ensuring DC, quorum and node attributes are up-to-date Nov 9 17:29:32 vm-1 crmd: [2478]: info: crm_update_quorum: Updating quorum status to true (call=72) Nov 9 17:29:32 vm-1 attrd: [2477]: notice: attrd_local_callback: Sending full refresh (origin=crmd) Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_pe_invoke: Query 73: Requesting the current CIB: S_POLICY_ENGINE Nov 9 17:29:32 vm-1 crmd: [2478]: info: te_update_diff: Detected LRM refresh - 11 resources updated: Skipping all resource events Nov 9 17:29:32 vm-1 crmd: [2478]: info: abort_transition_graph: te_update_diff:251 - Triggered transition abort (complete=1, tag=diff, id=(null), magic=NA, cib=1.30.182) : LRM Refresh Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_pe_invoke: Query 74: Requesting the current CIB: S_POLICY_ENGINE Nov 9 17:29:32 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_modify for section nodes (origin=local/crmd/70, version=1.30.183): ok (rc=0) Nov 9 17:29:32 vm-1 cib: [2474]: info: cib_process_request: Operation complete: op cib_modify for section cib (origin=local/crmd/72, version=1.30.185): ok (rc=0) Nov 9 17:29:32 vm-1 crmd: [2478]: info: do_pe_invoke_callback: Invoking the PE: query=74, ref=pe_calc-dc-1447108172-26, seq=59, quorate=1 Nov 9 17:29:32 vm-1 attrd: [2477]: notice: attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true) Thanks. --Shyam ___ Users mailing list: Users@clusterlabs.org http://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
Re: [ClusterLabs] heartbeat/pacemaker: stonith-ng does a broadcast that doesnt reach it back resulting stonith_async_timeout_handler() called
Hi Dejan,
Thanks a lot for your input!
I cherry picked this commit & this solves the problem. I will raise a
ubuntu launchpad bug for them to pull this correction in trusty stable.
Thanks!
--Shyam
On Thu, Oct 15, 2015 at 1:21 PM, Dejan Muhamedagic <deja...@fastmail.fm>
wrote:
> Hi,
>
> On Wed, Oct 14, 2015 at 10:31:40PM +0530, Shyam wrote:
> > Hi all,
> >
> > We were previously using Pacemaker 1.1.6 on Ubuntu Precise. We are
> shifting
> > to Ubuntu Trusty & it has Pacemaker 1.1.10.
> >
> > We have our own STONITH resource & with the pacemaker upgrade this is
> > broken. The problem that I am hitting is not something new & is exactly
> > that was reported in
> > http://clusterlabs.org/pipermail/users/2015-June/000686.html
> >
> > Basically Hearbeat + Pacemaker stack suffers this problem (even with the
> > github mainline code) & since a lot of people are using corosync I think
> > the problem is not felt with.
> >
> > The basic problem is this. Between Pacemaker 1.1.6 to 1.1.10, the
> following
> > change was done
> >
> > fencing/remote.c
> >
> > static void remote_op_done(remote_fencing_op_t * op, xmlNode * data, int
> > rc, int dup)
> >
> > if (dup == FALSE && safe_str_neq(subt, "broadcast")) {
> > /* Defer notification until the bcast message arrives */
> > bcast_result_to_peers(op, rc);
> > goto remote_op_done_cleanup;
> >
> > remote_op_done() previously used to send a direct reply. Now it was
> changed
> > that it does a broadcast of the result & this broadcast is supposed to
> come
> > back to the same fencing agent upon which finishes the operation. However
> > this broadcast that is being sent by stonithd doesnt reach back itself.
> > This causes eventually crmd to timeout on stonith_async_timeout_handler()
> > to be triggered & keep retrying STONITH. so essentially STONITH is
> broken.
>
> I can vaguelly recall some stonith/heartbeat issue which got
> fixed by Lars:
>
> commit cc34288a7b2276aa238546f4aa92fa79b8cbcf88
> Author: Lars Ellenberg <lars.ellenb...@linbit.com>
> Date: Tue Dec 9 10:48:33 2014 +0100
>
> Sounds like the same problem.
>
> Thanks,
>
> Dejan
>
>
> > I tried setting up bcast in /etc/ha.d/ha.cf, but it doesnt help. To
> confirm
> > the issue, I removed the above flow for bcast_result_to_peers() & then
> > STONITH works perfectly fine. Any pointers/help appreciated on how to
> > resolve this issue in the right way?
> >
> >
> > From logs
> >
> > CRMD issues STONITH reboot to stonith-ng
> >
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG: Dumping message
> with
> > 19 fields
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[0] :
> > [__name__=stonith_command]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[1] :
> > [__name__=stonith_command]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[2] : [t=stonith-ng]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[3] :
> > [st_async_id=617dce02-057f-42b8-9df2-33bc4e64780d]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[4] :
> [st_op=st_fence]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[5] : [st_callid=2]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[6] : [st_callopt=0]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[7] :
> > [st_remote_op=617dce02-057f-42b8-9df2-33bc4e64780d]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[8] :
> [st_target=node1]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[9] :
> > [st_device_action=reboot]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[10] :
> [st_origin=node0]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[11] :
> > [st_clientid=346fea6b-a55d-4873-b630-14287d5bc71e]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[12] :
> > [st_clientname=crmd.14483]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[13] :
> [st_timeout=90]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[14] :
> [st_mode=smart]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[15] : [dest=node0]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[16] : [oseq=2]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[17] :
> > [from_id=stonith-ng]
> > Oct 14 14:57:01 node0 heartbeat: [14463]: debug: MSG[18] :
> > [to_id=stonith-ng]
> >
> >
> > stonith-ng successfully finishes the STONITH
> > Oct 14 14:57:03 node0 stonith-ng[14481]: not
[ClusterLabs] heartbeat/pacemaker: stonith-ng does a broadcast that doesnt reach it back resulting stonith_async_timeout_handler() called
t 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[13] : [st_output=Performing: stonith -t external/zstonith -T reset node1#012success: node1 0#012] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[14] : [dest=node0] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[15] : [oseq=3] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[16] : [from_id=stonith-ng] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[17] : [to_id=stonith-ng] As part of this stonith-ng does a broadcast Oct 14 14:57:03 node0 stonith-ng[14481]:debug: stonith_command: Processing st_fence reply 0 from node0 ( 0) Oct 14 14:57:03 node0 stonith-ng[14481]:debug: remote_op_done: Broadcasting result Oct 14 14:57:03 node0 stonith-ng[14481]:debug: send_ha_message: outbound Oct 14 14:57:03 node0 stonith-ng[14481]:debug: send_ha_message: outbound Oct 14 14:57:03 node0 stonith-ng[14481]:debug: send_ha_message: outbound Oct 14 14:57:03 node0 stonith-ng[14481]:debug: send_ha_message: outbound Oct 14 14:57:03 node0 stonith-ng[14481]:debug: send_ha_message: outbound that is realized at hearbeat Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG: Dumping message with 8 fields Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[0] : [__name__=st-reply] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[1] : [t=st_notify] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[2] : [subt=broadcast] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[3] : [st_op=st_notify] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[4] : [count=1] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[5] : [st_calldata=] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[6] : [from_id=stonith-ng] Oct 14 14:57:03 node0 heartbeat: [14463]: debug: MSG[7] : [to_id=stonith-ng] but then on nothing really happens. eventually crmd gives up on timeout Oct 14 14:59:48 node0 crmd[14483]:error: stonith_async_timeout_handler: Async call 2 timed out after 168000ms Thanks. --Shyam ___ Users mailing list: Users@clusterlabs.org http://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
