[Pacemaker] [Problem]post_notify_start_0 is carried out in the node that disappeared.

[renayama19661014 at ybb.ne.jp]

Hi all,

We test trouble at the time of the start of the Master/Slave resource.

Step1) We start the first node and send cib.

============
Last updated: Thu Feb 10 16:32:12 2011
Stack: Heartbeat
Current DC: srv01 (c7435833-8bc5-43aa-8195-c666b818677f) - partition with quorum
Version: 1.0.10-b0266dd5ffa9c51377c68b1f29d6bc84367f51dd
1 Nodes configured, unknown expected votes
5 Resources configured.
============

Online: [ srv01 ]

prmIpPostgreSQLDB      (ocf::heartbeat:IPaddr2):       Started srv01
Resource Group: grpStonith2
     prmStonith2-2      (stonith:external/ssh): Started srv01
     prmStonith2-3      (stonith:meatware):     Started srv01
Master/Slave Set: msPostgreSQLDB
     Masters: [ srv01 ]
     Stopped: [ prmApPostgreSQLDB:1 ]
Clone Set: clnPingd
     Started: [ srv01 ]
     Stopped: [ prmPingd:1 ]

Migration summary:
* Node srv01: 


Step2) We change Stateful of the node of the second of them.
(snip)
stateful_start() {
    ocf_log info "Start of Stateful."
    sleep 120                            ----> add sleep.
    stateful_check_state master
(snip)

Step3) We start a node of the second of them.

Step4) We confirm "sleep" and reboot a node of the second of them.
[root at srv02 ~]# ps -ef |grep sleep

Step5) The node of the first of them detects the disappearance of the node of the second of them.
* But, STONITH is delayed because "post_notify_start_0" of the node of the second of them is carried
out.
* In the srv02 node that disappeared, we do not need the practice of post_notify_start_0.
* STONITH should be carried out immediately.(STONITH is kept waiting to time-out of
post_notify_start_0 now.)


--------------(snip)----------------
Feb 10 16:33:18 srv01 crmd: [4293]: info: ccm_event_detail: NEW MEMBERSHIP: trans=3, nodes=1, new=0,
lost=1 n_idx=0, new_idx=1, old_idx=3
Feb 10 16:33:18 srv01 crmd: [4293]: info: ccm_event_detail:     CURRENT: srv01 [nodeid=0, born=3]
Feb 10 16:33:18 srv01 crmd: [4293]: info: ccm_event_detail:     LOST:    srv02 [nodeid=1, born=2]
Feb 10 16:33:18 srv01 crmd: [4293]: info: ais_status_callback: status: srv02 is now lost (was member)
Feb 10 16:33:18 srv01 crmd: [4293]: info: crm_update_peer: Node srv02: id=1 state=lost (new)
addr=(null) votes=-1 born=2 seen=2 proc=00000000000000000000000000000200
Feb 10 16:33:18 srv01 crmd: [4293]: info: erase_node_from_join: Removed node srv02 from join
calculations: welcomed=0 itegrated=0 finalized=0 confirmed=1
Feb 10 16:33:18 srv01 crmd: [4293]: info: populate_cib_nodes_ha: Requesting the list of configured
nodes
Feb 10 16:33:19 srv01 crmd: [4293]: info: te_pseudo_action: Pseudo action 36 fired and confirmed
Feb 10 16:33:19 srv01 crmd: [4293]: info: te_pseudo_action: Pseudo action 39 fired and confirmed
Feb 10 16:33:19 srv01 crmd: [4293]: info: te_rsc_command: Initiating action 75: notify
prmApPostgreSQLDB:0_post_notify_start_0 on srv01 (local)
Feb 10 16:33:19 srv01 crmd: [4293]: info: do_lrm_rsc_op: Performing
key=75:7:0:6918f8dc-fe1a-4c28-8aff-e8ac7a5e7143 op=prmApPostgreSQLDB:0_notify_0 )
Feb 10 16:33:19 srv01 lrmd: [4290]: info: rsc:prmApPostgreSQLDB:0:24: notify
Feb 10 16:33:19 srv01 cib: [4289]: info: cib_process_request: Operation complete: op cib_modify for
section nodes (origin=local/crmd/99, version=0.9.22): ok (rc=0)
Feb 10 16:33:19 srv01 crmd: [4293]: info: te_rsc_command: Initiating action 76: notify
prmApPostgreSQLDB:1_post_notify_start_0 on srv02
Feb 10 16:33:19 srv01 lrmd: [4290]: info: RA output: (prmApPostgreSQLDB:0:notify:stdout) usage:
/usr/lib/ocf/resource.d//pacemaker/Stateful {start|stop|promote|demote|monitor|validate-all|meta-data}
Expects to have a fully populated OCF RA-compliant environment set.
Feb 10 16:33:19 srv01 crmd: [4293]: info: process_lrm_event: LRM operation
prmApPostgreSQLDB:0_notify_0 (call=24, rc=0, cib-update=101, confirmed=true) ok
Feb 10 16:33:19 srv01 crmd: [4293]: info: match_graph_event: Action
prmApPostgreSQLDB:0_post_notify_start_0 (75) confirmed on srv01 (rc=0)
Feb 10 16:33:19 srv01 crmd: [4293]: info: te_pseudo_action: Pseudo action 40 fired and confirmed
Feb 10 16:34:39 srv01 crmd: [4293]: WARN: action_timer_callback: Timer popped (timeout=20000,
abort_level=1000000, complete=false)
Feb 10 16:34:39 srv01 crmd: [4293]: ERROR: print_elem: Aborting transition, action lost: [Action 76]:
Failed (id: prmApPostgreSQLDB:1_post_notify_start_0, loc: srv02, priority: 1000000)
Feb 10 16:34:39 srv01 crmd: [4293]: info: abort_transition_graph: action_timer_callback:486 -
Triggered transition abort (complete=0) : Action lost
Feb 10 16:34:39 srv01 crmd: [4293]: WARN: cib_action_update: rsc_op 76:
prmApPostgreSQLDB:1_post_notify_start_0 on srv02 timed out
Feb 10 16:34:39 srv01 crmd: [4293]: info: run_graph:
====================================================
Feb 10 16:34:39 srv01 crmd: [4293]: notice: run_graph: Transition 7 (Complete=16, Pending=0, Fired=0,
Skipped=1, Incomplete=0, Source=/var/lib/pengine/pe-input-7.bz2): Stopped
Feb 10 16:34:39 srv01 crmd: [4293]: info: te_graph_trigger: Transition 7 is now complete
Feb 10 16:34:39 srv01 crmd: [4293]: info: do_state_transition: State transition S_TRANSITION_ENGINE ->
S_POLICY_ENGINE [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ]
---------------(snip)------------------

Will not this movement be bug?

 *  I registered the log with Bugzilla.
 * http://developerbugs.linux-foundation.org/show_bug.cgi?id=2559

Best Regards,
Hideo Yamauchi.