[Pacemaker] Need help with resolving very long election cycle
Shyam
shyam.kaushik at gmail.com
Thu Feb 16 11:59:09 UTC 2012
Hi Andrew,
Did you get a chance to look at the below logs? Anything that needs to be
setup differently in the config?
Thanks.
--Shyam
On Thu, Feb 9, 2012 at 10:13 AM, Shyam <shyam.kaushik at gmail.com> wrote:
> Hi Andrew,
>
> I don't have below log files anymore. I captured fresh set of logs. Please
> find it attached. Thanks.
>
> --Shyam
>
> On Wed, Feb 8, 2012 at 6:29 AM, Andrew Beekhof <andrew at beekhof.net> wrote:
>
>> On Fri, Feb 3, 2012 at 4:20 PM, Shyam <shyam.kaushik at gmail.com> wrote:
>> > Hi Andrew,
>> >
>> > We are using Pacemaker version:1.0.10-4ubuntu3 (comes with Ubuntu Natty
>> > 11.04)
>> >
>> > I captured logs with higher debug.
>>
>> I'm hoping you still have those logs.
>> I need the lines /before/ this one:
>> Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: info:
>> crm_timer_popped: Election Trigger (I_DC_TIMEOUT) just popped!
>>
>> Everything after looks in order
>>
>> >
>> > On node-1
>> >
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: info: crm_timer_popped:
>> > Election Trigger (I_DC_TIMEOUT) just popped!
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Stopping Election Trigger (I_DC_TIMEOUT:5000ms), src=16
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: crm_timer_popped appended FSA input 9
>> (I_DC_TIMEOUT)
>> > (cause=C_TIMER_POPPED) without data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crm_timer_popped: Triggering FSA: crm_timer_popped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 1)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_PENDING
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 9
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 9
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Processing peer message (vsa-0000004dc-vc-1) for
>> > master...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing input from crm_timer_popped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > parse_peer_options: Ignoring msg for master instance
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: s_crmd_fsa:
>> > Processing I_DC_TIMEOUT: [ state=S_PENDING cause=C_TIMER_POPPED
>> > origin=crm_timer_popped ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_WARN
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: WARN: do_log: FSA:
>> Input
>> > I_DC_TIMEOUT from crm_timer_popped() received in state S_PENDING
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_state_transition: actions:trace: #011S_PENDING -> S_ELECTION [
>> > label=I_DC_TIMEOUT cause=C_TIMER_POPPED origin=crm_timer_popped ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: info:
>> do_state_transition:
>> > State transition S_PENDING -> S_ELECTION [ input=I_DC_TIMEOUT
>> > cause=C_TIMER_POPPED origin=crm_timer_popped ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: PEngine Recheck Timer (I_PE_CALC:900000ms) already
>> stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_state_transition: Resetting our DC to NULL on transition to
>> S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_INTEGRATE_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Integration Timer (I_INTEGRATED:180000ms) already
>> stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_FINALIZE_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Finalization Timer (I_ELECTION:1800000ms) already
>> stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_VOTE
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-3" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="2" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_vote:
>> > Started election 2
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: crm_timer_start:
>> > Started Election Timeout (I_ELECTION_DC:120000ms), src=17
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: join_offer from vsa-0000004dc-vc-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Routing message join_offer-dc-1328245368-5
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="join_make_offer" t="crmd" version="3.0.1" subt="request"
>> > reference="join_offer-dc-1328245368-5" crm_task="join_offer"
>> > crm_sys_to="crmd" crm_sys_from="dc" crm_host_to="vsa-0000004dc-vc-0"
>> > join_id="1" dest="vsa-0000004dc-vc-0" oseq="1" from_id="crmd"
>> to_id="crmd"
>> > client_gen="4" src="vsa-0000004dc-vc-1" seq="2f" hg="4f2a227c"
>> ts="4f2b6a79"
>> > ld="3.01 0.88 0.30 5/106 1372" ttl="3" auth="1
>> > d2e4a8a0ea8382763ce1ecd42633b575453fee2f" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: handle_request:
>> > Raising I_JOIN_OFFER: join-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: route_message appended FSA input 10
>> (I_JOIN_OFFER)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from route_message as
>> a HA
>> > msg
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-3
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-3" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="2" oseq="1" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-0" seq="2f" hg="4f2a2274" ts="4f2b6a79" ld="2.89
>> 0.85
>> > 0.29 7/105 1463" ttl="3" auth="1
>> 36b49d6fb3fb61ca4d5da0e98380e36d62f42449"
>> > />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 11 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG:
>> Dumping
>> > message with 14 fields
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[1] :
>> > [origin=do_election_vote]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 2)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[5] :
>> > [reference=vote-crmd-1328245369-3]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[6] :
>> > [crm_task=vote]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from route_message
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[9] :
>> > [election-owner=00001244-1244-0000-2b91-000000000000]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: s_crmd_fsa:
>> > Processing I_JOIN_OFFER: [ state=S_ELECTION cause=C_HA_MESSAGE
>> > origin=route_message ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[10] :
>> > [election-id=2]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_WARN
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[11] :
>> > [oseq=1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: WARN: do_log: FSA:
>> Input
>> > I_JOIN_OFFER from route_message() received in state S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[12] :
>> > [from_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_JOIN_OFFER #011Origin=route_message() #011id=10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[13] :
>> > [to_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_VOTE
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-4" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="3" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_vote:
>> > Started election 3
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: crm_timer_start:
>> > Election Timeout (I_ELECTION_DC:120000ms) already running: src=17
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: return 1;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> > do_election_count_vote: Created voted hash
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > do_election_count_vote: Election 2 (current: 3, owner:
>> > 00001244-1244-0000-2b91-000000000000): Processed vote from
>> > vsa-0000004dc-vc-0 (Superceeded)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_check:
>> > Still waiting on 2 non-votes (2 total)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-4
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG:
>> Dumping
>> > message with 14 fields
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-4" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="3" oseq="2" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-0" seq="30" hg="4f2a2274" ts="4f2b6a79" ld="2.89
>> 0.85
>> > 0.29 2/105 1463" ttl="3" auth="1
>> 51ab53d3e8bcd21bf244b526b9d9e00ff229781b"
>> > />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[1] :
>> > [origin=do_election_vote]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 12 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[5] :
>> > [reference=vote-crmd-1328245369-4]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[6] :
>> > [crm_task=vote]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 1)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[9] :
>> > [election-owner=00001244-1244-0000-2b91-000000000000]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[10] :
>> > [election-id=3]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[11] :
>> > [oseq=2]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[12] :
>> > [from_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[13] :
>> > [to_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> > do_election_count_vote: Election 3 (current: 3, owner:
>> > 00001244-1244-0000-2b91-000000000000): Processed vote from
>> > vsa-0000004dc-vc-0 (Recorded)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: return 1;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-0) for
>> > master...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > parse_local_options: Processing locally scoped cib_slave op from crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-6
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_readwrite: Processing "cib_slave" event
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Operation complete: op cib_slave for section 'all'
>> > (origin=local/crmd/6, version=1.2.0): ok (rc=0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-6" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="3" oseq="2" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-1" seq="31" hg="4f2a227c" ts="4f2b6a7a" ld="3.01
>> 0.88
>> > 0.30 5/106 1372" ttl="3" auth="1
>> 27a5f24827f1ca0d08946dea098d0a43404f341a"
>> > />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: processing response cases
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 13 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Performing notification
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > do_local_notify: Sending callback to request originator
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Sending an a-sync response to crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering msg 0x2097a20 to client
>> > e718aaee-f618-4089-a952-11ad7da65c09
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering reply to client
>> > e718aaee-f618-4089-a952-11ad7da65c09 (cib_callback)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Completed slave update
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: join_request from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-0) for
>> > master...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > parse_local_options: Processing locally scoped cib_slave op from crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245370-8
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_readwrite: Processing "cib_slave" event
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245370-8" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="4" oseq="4" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-1" seq="33" hg="4f2a227c" ts="4f2b6a7a" ld="3.01
>> 0.88
>> > 0.30 4/106 1372" ttl="3" auth="1
>> 4cb5c076b4cd9b89a4c5daa0866b59ccb8158a58"
>> > />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Operation complete: op cib_slave for section 'all'
>> > (origin=local/crmd/7, version=1.2.0): ok (rc=0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 14 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: processing response cases
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Performing notification
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > do_local_notify: Sending callback to request originator
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Sending an a-sync response to crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering msg 0x2097a20 to client
>> > e718aaee-f618-4089-a952-11ad7da65c09
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering reply to client
>> > e718aaee-f618-4089-a952-11ad7da65c09 (cib_callback)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 2)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Completed slave update
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-0) for
>> > master...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > parse_local_options: Processing locally scoped cib_slave op from crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_readwrite: Processing "cib_slave" event
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Operation complete: op cib_slave for section 'all'
>> > (origin=local/crmd/8, version=1.2.0): ok (rc=0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > cib_process_request: processing response cases
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Performing notification
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > do_local_notify: Sending callback to request originator
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > do_local_notify: Sending an a-sync response to crmd
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering msg 0x2097a20 to client
>> > e718aaee-f618-4089-a952-11ad7da65c09
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> > do_election_count_vote: Election 3 (owner:
>> > 00001244-1244-0001-2b91-000000000001) lost: vote from vsa-0000004dc-vc-1
>> > (Age)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug3:
>> > send_via_callback_channel: Delivering reply to client
>> > e718aaee-f618-4089-a952-11ad7da65c09 (cib_callback)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms),
>> src=17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug: debug2:
>> > cib_process_request: Completed slave update
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > do_election_count_vote: We werent the DC anyway
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 cib: [1255]: debug:
>> > cib_common_callback_worker: Setting cib_diff_notify callbacks for 1259
>> > (e718aaee-f618-4089-a952-11ad7da65c09): off
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: do_election_count_vote appended FSA input 15
>> > (I_PENDING) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_count_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="no-vote-crmd-1328245370-5" crm_task="no-vote"
>> crm_sys_to="crmd"
>> > crm_sys_from="crmd" crm_host_to="vsa-0000004dc-vc-1"
>> > election-owner="00001244-1244-0001-2b91-000000000001" election-id="3" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Sending cib_slave message to CIB service
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Message sent
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Async call, returning
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG:
>> Dumping
>> > message with 16 fields
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[1] :
>> > [origin=do_election_count_vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[5] :
>> > [reference=no-vote-crmd-1328245370-5]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[6] :
>> > [crm_task=no-vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> > do_election_count_vote: Election 4 (owner:
>> > 00001244-1244-0001-2b91-000000000001) lost: vote from vsa-0000004dc-vc-1
>> > (Age)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Election Timeout (I_ELECTION_DC:120000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[9] :
>> > [crm_host_to=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > do_election_count_vote: We werent the DC anyway
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[10] :
>> > [election-owner=00001244-1244-0001-2b91-000000000001]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: do_election_count_vote appended FSA input 16
>> > (I_PENDING) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[11] :
>> > [election-id=3]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[12] :
>> > [dest=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[13] :
>> > [oseq=2]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_count_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="no-vote-crmd-1328245370-6" crm_task="no-vote"
>> crm_sys_to="crmd"
>> > crm_sys_from="crmd" crm_host_to="vsa-0000004dc-vc-1"
>> > election-owner="00001244-1244-0001-2b91-000000000001" election-id="4" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[14] :
>> > [from_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Sending cib_slave message to CIB service
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[15] :
>> > [to_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Message sent
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Async call, returning
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: return 1;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 15
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 15
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_election_count_vote
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: s_crmd_fsa:
>> > Processing I_PENDING: [ state=S_ELECTION cause=C_FSA_INTERNAL
>> > origin=do_election_count_vote ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG:
>> Dumping
>> > message with 16 fields
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_state_transition: actions:trace: #011S_ELECTION -> S_PENDING [
>> > label=I_PENDING cause=C_FSA_INTERNAL origin=do_election_count_vote ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: info:
>> do_state_transition:
>> > State transition S_ELECTION -> S_PENDING [ input=I_PENDING
>> > cause=C_FSA_INTERNAL origin=do_election_count_vote ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[1] :
>> > [origin=do_election_count_vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Election Timeout (I_ELECTION_DC:120000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: PEngine Recheck Timer (I_PE_CALC:900000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Sending cib_slave message to CIB service
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Message sent
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[5] :
>> > [reference=no-vote-crmd-1328245370-6]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_perform_op: Async call, returning
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[6] :
>> > [crm_task=no-vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_state_transition: Resetting our DC to NULL on transition to S_PENDING
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[9] :
>> > [crm_host_to=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_INTEGRATE_TIMER_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[10] :
>> > [election-owner=00001244-1244-0001-2b91-000000000001]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Integration Timer (I_INTEGRATED:180000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[11] :
>> > [election-id=4]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_FINALIZE_TIMER_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[12] :
>> > [dest=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Finalization Timer (I_ELECTION:1800000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[13] :
>> > [oseq=3]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_START
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[14] :
>> > [from_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: crm_timer_start:
>> > Started Election Trigger (I_DC_TIMEOUT:5000ms), src=18
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: MSG[15] :
>> > [to_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_RELEASE
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_dc_release:
>> > Releasing the role of DC
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_dc_release: Am I still the DC? false
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_RELEASED
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: info: do_dc_release: DC
>> > role released
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: return 1;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: do_dc_release appended FSA input 17
>> > (I_RELEASE_SUCCESS) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > do_dc_release: Am I still the DC? false
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_PE_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > stop_subsystem: Stopping sub-system "pengine"
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > stop_subsystem: Client pengine not running
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_TE_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug:
>> > cib_client_del_notify_callback: Removing callback for cib_diff_notify
>> events
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_client_del_notify_callback: Callback not present
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: info: do_te_control:
>> > Transitioner is now inactive
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_election_count_vote
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: s_crmd_fsa:
>> > Processing I_PENDING: [ state=S_PENDING cause=C_FSA_INTERNAL
>> > origin=do_election_count_vote ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_LOG
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2: do_log:
>> FSA:
>> > Input I_PENDING from do_election_count_vote() received in state
>> S_PENDING
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_PENDING
>> #011Cause=C_FSA_INTERNAL
>> > #011Input=I_PENDING #011Origin=do_election_count_vote() #011id=16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_timer_stop: Stopping Election Trigger (I_DC_TIMEOUT:5000ms), src=18
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_START
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: crm_timer_start:
>> > Started Election Trigger (I_DC_TIMEOUT:5000ms), src=19
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> get_message:
>> > Processing input 17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > log_fsa_input: Processing queued input 17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_dc_release
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: s_crmd_fsa:
>> > Processing I_RELEASE_SUCCESS: [ state=S_PENDING cause=C_FSA_INTERNAL
>> > origin=do_dc_release ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: do_fsa_action:
>> > actions:trace: #011// A_LOG
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2: do_log:
>> FSA:
>> > Input I_RELEASE_SUCCESS from do_dc_release() received in state S_PENDING
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_PENDING
>> #011Cause=C_FSA_INTERNAL
>> > #011Input=I_RELEASE_SUCCESS #011Origin=do_dc_release() #011id=17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_PENDING
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > cib_native_callback: No callback found for call 6
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > cib_native_callback: No callback found for call 7
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug2:
>> > cib_native_callback: No callback found for call 8
>> > Feb 3 07:02:50 vsa-0000004dc-vc-0 crmd: [1259]: debug: debug3:
>> > cib_native_msgready: No message pending
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: PID 1018:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-0 heartbeat: [1018]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:55 vsa-0000004dc-vc-0 crmd: [1259]: info: crm_timer_popped:
>> > Election Trigger (I_DC_TIMEOUT) just popped!
>> >
>> >
>> > on node-2
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 12 fields
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=copy]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [__name__=cib_command]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=cib]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [cib_clientid=fd2ec03c-a9c3-4a90-b6b7-2eb26eb24545]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [cib_callopt=0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [cib_callid=5]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [cib_op=cib_slave_all]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [cib_async_id=aa13a017-01bf-4589-af6c-084cec13f6fa]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [cib_clientname=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [cib_delegated_from=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [from_id=cib]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [to_id=cib]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 15 fields
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [origin=join_make_offer]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [reference=join_offer-dc-1328245368-4]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [crm_task=join_offer]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [crm_sys_from=dc]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [crm_host_to=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [join_id=1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [dest=vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[12] :
>> > [oseq=1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[13] :
>> > [from_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[14] :
>> > [to_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 15 fields
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [origin=join_make_offer]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [reference=join_offer-dc-1328245368-5]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [crm_task=join_offer]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [crm_sys_from=dc]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [crm_host_to=vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [join_id=1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [dest=vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[12] :
>> > [oseq=1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[13] :
>> > [from_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[14] :
>> > [to_id=crmd]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug: IPC
>> accepted a
>> > connection.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-1) for
>> > master...
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: stonithd_signon:
>> > creating connection
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > G_main_IPC_Channel_constructor(sock=7,7)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > parse_local_options: Processing locally scoped cib_query op from crmd
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: sending out the
>> > signon msg.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_client_dispatch: begin
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: signed on to
>> > stonithd.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug: begin to
>> dealing
>> > with a api msg signon from a client PID:1073.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_query: Processing "cib_query" event for section=<null>
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > te_connect_stonith: Grabbing IPC channel
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > on_stonithd_signon: begin.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> xpath_search:
>> > Evaluating: //cib
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > te_connect_stonith: Attaching to mainloop
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > get_exist_client_by_chan: begin.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Operation complete: op cib_query for section 'all'
>> > (origin=local/crmd/13, version=1.2.0): ok (rc=0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > G_main_IPC_Channel_constructor(sock=15,15)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug: client
>> tengine
>> > (pid=1073) succeeded to signon to stonithd.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > cib_process_request: processing response cases
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> te_connect_stonith:
>> > Connected
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_process_client_msg: end.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > do_local_notify: Performing notification
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: No callback found for call 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_client_dispatch: end
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > do_local_notify: Sending callback to request originator
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: Invoking global callback for call 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug: IPC
>> accepted a
>> > callback connection.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > do_local_notify: Sending an a-sync response to crmd
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: Invoking callback config_query_callback for call 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > G_main_IPC_Channel_constructor(sock=9,9)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > send_via_callback_channel: Delivering msg 0x805700 to client
>> > aa13a017-01bf-4589-af6c-084cec13f6fa
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > config_query_callback: Call 12 : Parsing CIB options
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_client_dispatch: begin
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > send_via_callback_channel: Delivering reply to client
>> > aa13a017-01bf-4589-af6c-084cec13f6fa (cib_callback)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > unpack_attr_set: Adding attributes from cib-bootstrap-options
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_process_client_msg: received signon request from callback
>> channel.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Completed slave update
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '15min' for cluster option
>> 'cluster-recheck-interval'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > on_stonithd_cookie: begin.
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '2min' for cluster option 'election-timeout'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 stonithd: [1071]: debug:
>> > stonithd_client_dispatch: end
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '20min' for cluster option 'shutdown-escalation'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '3min' for cluster option 'crmd-integration-timeout'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '30min' for cluster option
>> 'crmd-finalization-timeout'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: cluster_option:
>> > Using default value '2' for cluster option 'expected-quorum-votes'
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> > config_query_callback: Checking for expired actions every 900000ms
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > config_query_callback: Triggering FSA: config_query_callback
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: Invoking global callback for call 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_msgready: No message pending
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: join_offer from vsa-0000004dc-vc-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message join_offer-dc-1328245368-4
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="join_make_offer" t="crmd" version="3.0.1" subt="request"
>> > reference="join_offer-dc-1328245368-4" crm_task="join_offer"
>> > crm_sys_to="crmd" crm_sys_from="dc" crm_host_to="vsa-0000004dc-vc-1"
>> > join_id="1" dest="vsa-0000004dc-vc-1" oseq="1" from_id="crmd"
>> to_id="crmd"
>> > client_gen="4" src="vsa-0000004dc-vc-1" seq="2e" hg="4f2a227c"
>> ts="4f2b6a79"
>> > ld="3.01 0.88 0.30 5/106 1372" ttl="3" auth="1
>> > 6e4e4efdb36e7856aab1cd016e0fcd011ce99908" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: handle_request:
>> > Raising I_JOIN_OFFER: join-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: route_message appended FSA input 10
>> (I_JOIN_OFFER)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from route_message as
>> a HA
>> > msg
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-3
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-3" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="2" oseq="1" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-0" seq="2f" hg="4f2a2274" ts="4f2b6a79" ld="2.89
>> 0.85
>> > 0.29 7/105 1463" ttl="3" auth="1
>> 36b49d6fb3fb61ca4d5da0e98380e36d62f42449"
>> > />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 11 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 2)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_INTEGRATION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from route_message
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: s_crmd_fsa:
>> > Processing I_JOIN_OFFER: [ state=S_INTEGRATION cause=C_HA_MESSAGE
>> > origin=route_message ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_INTEGRATION
>> #011Cause=C_HA_MESSAGE
>> > #011Input=I_JOIN_OFFER #011Origin=route_message() #011id=10
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_CL_JOIN_REQUEST
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > do_cl_join_offer_respond: Accepting join offer: join-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info: update_dc: Set
>> DC to
>> > vsa-0000004dc-vc-1 (3.0.1)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Sending cib_query message to CIB service
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Message sent
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Async call, returning
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > do_cl_join_offer_respond: Registered join query callback: 13
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_cl_join_offer_respond: do_cl_join_offer_respond added action
>> > A_DC_TIMER_STOP to the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_INTEGRATION
>> #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=11
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Created voted hash
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> > do_election_count_vote: Election 2 (owner:
>> > 00001244-1244-0000-2b91-000000000000) pass: vote from vsa-0000004dc-vc-0
>> > (Age)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: do_election_count_vote appended FSA input 12
>> > (I_ELECTION) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Ignore election check: we not in an election
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 12
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_election_count_vote
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: s_crmd_fsa:
>> > Processing I_ELECTION: [ state=S_INTEGRATION cause=C_FSA_INTERNAL
>> > origin=do_election_count_vote ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > do_state_transition: actions:trace: #011S_INTEGRATION -> S_ELECTION [
>> > label=I_ELECTION cause=C_FSA_INTERNAL origin=do_election_count_vote ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> do_state_transition:
>> > State transition S_INTEGRATION -> S_ELECTION [ input=I_ELECTION
>> > cause=C_FSA_INTERNAL origin=do_election_count_vote ]
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: PEngine Recheck Timer (I_PE_CALC:900000ms) already
>> stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > do_state_transition: Resetting our DC to NULL on transition to
>> S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: info: update_dc: Unset
>> DC
>> > vsa-0000004dc-vc-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_INTEGRATE_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Stopping Integration Timer (I_INTEGRATED:180000ms),
>> src=19
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_FINALIZE_TIMER_STOP
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Finalization Timer (I_ELECTION:1800000ms) already
>> stopped
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_VOTE
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-6" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="3" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_vote:
>> > Started election 3
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: crm_timer_start:
>> > Started Election Timeout (I_ELECTION_DC:120000ms), src=24
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: Invoking callback join_query_callback for call 13
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> join_query_callback:
>> > Respond to join offer join-1
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> join_query_callback:
>> > Acknowledging (null) as our DC
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="join_query_callback" t="crmd" version="3.0.1" subt="request"
>> > reference="join_request-crmd-1328245369-7" crm_task="join_request"
>> > crm_sys_to="dc" crm_sys_from="crmd" join_id="1" >
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <crm_xml >
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <generation_tuple
>> > validate-with="pacemaker-1.0" crm_feature_set="3.0.1" have-quorum="1"
>> > epoch="2" admin_epoch="1" num_updates="0" cib-last-written="Thu Feb 2
>> > 07:44:09 2012" />
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] </crm_xml>
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] </create_request_adv>
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > cib_native_callback: Invoking global callback for call 13
>> > Feb 3 07:02:49 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_msgready: No message pending
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-4
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-4" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0000-2b91-000000000000"
>> > election-id="3" oseq="2" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-0" seq="30" hg="4f2a2274" ts="4f2b6a79" ld="2.89
>> 0.85
>> > 0.29 2/105 1463" ttl="3" auth="1
>> 51ab53d3e8bcd21bf244b526b9d9e00ff229781b"
>> > />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 13 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245369-6
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245369-6" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="3" oseq="2" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-1" seq="31" hg="4f2a227c" ts="4f2b6a7a" ld="3.01
>> 0.88
>> > 0.30 5/106 1372" ttl="3" auth="1
>> 27a5f24827f1ca0d08946dea098d0a43404f341a"
>> > />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 14 fields
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 14 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [origin=do_election_vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [reference=vote-crmd-1328245369-6]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: join_request from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [crm_task=vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message join_request-crmd-1328245369-7
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: DC/CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="join_query_callback" t="crmd" version="3.0.1" subt="request"
>> > reference="join_request-crmd-1328245369-7" crm_task="join_request"
>> > crm_sys_to="dc" crm_sys_from="crmd" join_id="1" oseq="3" from_id="crmd"
>> > to_id="crmd" client_gen="4" src="vsa-0000004dc-vc-1" seq="32"
>> hg="4f2a227c"
>> > ts="4f2b6a7a" ld="3.01 0.88 0.30 5/106 1372" ttl="3" auth="1
>> > 30d8bfc913c4f2ecf2fef96420e1f98e6dbf97e4" >
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [election-owner=00001244-1244-0001-2b91-000000000001]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <crm_xml >
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [election-id=3]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <generation_tuple
>> > validate-with="pacemaker-1.0" crm_feature_set="3.0.1" have-quorum="1"
>> > epoch="2" admin_epoch="1" num_updates="0" cib-last-written="Thu Feb 2
>> > 07:44:09 2012" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [oseq=2]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log </crm_xml>
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[12] :
>> > [from_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log </create_request_adv>
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[13] :
>> > [to_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: route_message appended FSA input 15
>> (I_JOIN_REQUEST)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from route_message as
>> a HA
>> > msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 3
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 3)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (3 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 14 fields
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [origin=join_query_callback]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=13
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Created voted hash
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [reference=join_request-crmd-1328245369-7]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [crm_task=join_request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > compare_version: 3.0.1 == 3.0.1 (4)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [crm_sys_to=dc]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> > do_election_count_vote: Election 3 (owner:
>> > 00001244-1244-0000-2b91-000000000000) pass: vote from vsa-0000004dc-vc-0
>> > (Age)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: do_election_count_vote appended FSA input 16
>> > (I_ELECTION) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [join_id=1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 3
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [crm_xml=<crm_xml><generation_tuple validate-with="pacemaker-1.0"
>> > crm_feature_set="3.0.1" have-quorum="1" epoch="2" admin_epoch="1"
>> > num_updates="0" cib-last-written="Thu Feb 2 07:44:09 2012"/></crm_xml>]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [oseq=3]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[12] :
>> > [from_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Still waiting on 2 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[13] :
>> > [to_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (3 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=14
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > APIclients_input_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > ProcessAnAPIRequest() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Created voted hash
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Sending API
>> > message to cluster...
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Election 3 (current: 3, owner:
>> > 00001244-1244-0001-2b91-000000000001): Processed vote from
>> > vsa-0000004dc-vc-1 (Recorded)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG:
>> Dumping
>> > message with 14 fields
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[0] :
>> > [__name__=create_request_adv]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[1] :
>> > [origin=do_election_vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[2] :
>> > [t=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 15
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[3] :
>> > [version=3.0.1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 15
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[4] :
>> > [subt=request]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from route_message
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[5] :
>> > [reference=vote-crmd-1328245370-8]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: log_fsa_input: FSA message data <generation_tuple
>> > validate-with="pacemaker-1.0" crm_feature_set="3.0.1" have-quorum="1"
>> > epoch="2" admin_epoch="1" num_updates="0" cib-last-written="Thu Feb 2
>> > 07:44:09 2012" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[6] :
>> > [crm_task=vote]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: s_crmd_fsa:
>> > Processing I_JOIN_REQUEST: [ state=S_ELECTION cause=C_HA_MESSAGE
>> > origin=route_message ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[7] :
>> > [crm_sys_to=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_WARN
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[8] :
>> > [crm_sys_from=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: WARN: do_log: FSA:
>> Input
>> > I_JOIN_REQUEST from route_message() received in state S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[9] :
>> > [election-owner=00001244-1244-0001-2b91-000000000001]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_JOIN_REQUEST #011Origin=route_message() #011id=15
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[10] :
>> > [election-id=4]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[11] :
>> > [oseq=4]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[12] :
>> > [from_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: MSG[13] :
>> > [to_id=crmd]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_election_count_vote
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: s_crmd_fsa:
>> > Processing I_ELECTION: [ state=S_ELECTION cause=C_FSA_INTERNAL
>> > origin=do_election_count_vote ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: #011return
>> > TRUE;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION
>> #011Cause=C_FSA_INTERNAL
>> > #011Input=I_ELECTION #011Origin=do_election_count_vote() #011id=16
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*ProcessAnAPIRequest*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_VOTE
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: return 1;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: send_ha_message: HA[outbound] <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245370-8" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="4" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*APIclients_input_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_vote:
>> > Started election 4
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: crm_timer_start:
>> > Election Timeout (I_ELECTION_DC:120000ms) already running: src=24
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: vote from vsa-0000004dc-vc-1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message vote-crmd-1328245370-8
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="vote-crmd-1328245370-8" crm_task="vote" crm_sys_to="crmd"
>> > crm_sys_from="crmd"
>> election-owner="00001244-1244-0001-2b91-000000000001"
>> > election-id="4" oseq="4" from_id="crmd" to_id="crmd" client_gen="4"
>> > src="vsa-0000004dc-vc-1" seq="33" hg="4f2a227c" ts="4f2b6a7a" ld="3.01
>> 0.88
>> > 0.30 4/106 1372" ttl="3" auth="1
>> 4cb5c076b4cd9b89a4c5daa0866b59ccb8158a58"
>> > />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 17 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 1)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=17
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Created voted hash
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Election 4 (current: 4, owner:
>> > 00001244-1244-0001-2b91-000000000001): Processed vote from
>> > vsa-0000004dc-vc-1 (Recorded)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Exiting the FSA
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Exited (queue len: 0)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > ha_msg_dispatch: Invoked
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: no-vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message no-vote-crmd-1328245370-5
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_count_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="no-vote-crmd-1328245370-5" crm_task="no-vote"
>> crm_sys_to="crmd"
>> > crm_sys_from="crmd" crm_host_to="vsa-0000004dc-vc-1"
>> > election-owner="00001244-1244-0001-2b91-000000000001" election-id="3"
>> > dest="vsa-0000004dc-vc-1" oseq="2" from_id="crmd" to_id="crmd"
>> > client_gen="4" src="vsa-0000004dc-vc-0" seq="32" hg="4f2a2274"
>> ts="4f2b6a7a"
>> > ld="2.89 0.85 0.29 4/105 1463" ttl="3" auth="1
>> > 0ded73bd06ebe658943f0f73fae2151b9cb6b229" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 18 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crmd_ha_msg_callback: HA[inbound]: no-vote from vsa-0000004dc-vc-0
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Routing message no-vote-crmd-1328245370-6
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > relay_message: Router result: Message result: CRMd process
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_data_element: relay_message: router.log <create_request_adv
>> > origin="do_election_count_vote" t="crmd" version="3.0.1" subt="request"
>> > reference="no-vote-crmd-1328245370-6" crm_task="no-vote"
>> crm_sys_to="crmd"
>> > crm_sys_from="crmd" crm_host_to="vsa-0000004dc-vc-1"
>> > election-owner="00001244-1244-0001-2b91-000000000001" election-id="4"
>> > dest="vsa-0000004dc-vc-1" oseq="3" from_id="crmd" to_id="crmd"
>> > client_gen="4" src="vsa-0000004dc-vc-0" seq="33" hg="4f2a2274"
>> ts="4f2b6a7a"
>> > ld="2.89 0.85 0.29 6/105 1463" ttl="3" auth="1
>> > 0c66fc873f3832778ad31f85d1a81778da4de475" />
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: handle_request appended FSA input 19 (I_NULL)
>> > (cause=C_HA_MESSAGE) with data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Adding actions 0000000200000400 to input
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Copying C_HA_MESSAGE data from handle_request
>> as a
>> > HA msg
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 2
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > crmd_ha_msg_filter: Triggering FSA: crmd_ha_msg_filter
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_fsa_trigger: Invoked (queue len: 2)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > FSA invoked with Cause: C_FSA_INTERNAL#011State: S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (2 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 18
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 18
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=18
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > do_election_count_vote: Election 3 (current: 4, owner:
>> > 00001244-1244-0001-2b91-000000000001): Processed no-vote from
>> > vsa-0000004dc-vc-0 (Superceeded)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Still waiting on 1 non-votes (2 total)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 19
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 19
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing XML message from handle_request
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > print_xml_formatted: log_fsa_input: FSA message data: NULL
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > actions:trace: #011// FSA input: State=S_ELECTION #011Cause=C_HA_MESSAGE
>> > #011Input=I_NULL #011Origin=handle_request() #011id=19
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_COUNT
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > do_election_count_vote: Election 4 (current: 4, owner:
>> > 00001244-1244-0001-2b91-000000000001): Processed no-vote from
>> > vsa-0000004dc-vc-0 (Recorded)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_ELECTION_CHECK
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Stopping Election Timeout (I_ELECTION_DC:120000ms),
>> src=24
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: do_election_check appended FSA input 20
>> > (I_ELECTION_DC) (cause=C_FSA_INTERNAL) without data
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > register_fsa_input_adv: Queue len: 1
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > register_fsa_input_adv: Triggering FSA: register_fsa_input_adv
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> do_election_check:
>> > Destroying voted hash
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> s_crmd_fsa:
>> > Checking messages (1 remaining)
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> get_message:
>> > Processing input 20
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > log_fsa_input: Processing queued input 20
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > log_fsa_input: FSA processing input from do_election_check
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: s_crmd_fsa:
>> > Processing I_ELECTION_DC: [ state=S_ELECTION cause=C_FSA_INTERNAL
>> > origin=do_election_check ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_LOG
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2: do_log:
>> FSA:
>> > Input I_ELECTION_DC from do_election_check() received in state
>> S_ELECTION
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > do_state_transition: actions:trace: #011S_ELECTION -> S_INTEGRATION [
>> > label=I_ELECTION_DC cause=C_FSA_INTERNAL origin=do_election_check ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: info:
>> do_state_transition:
>> > State transition S_ELECTION -> S_INTEGRATION [ input=I_ELECTION_DC
>> > cause=C_FSA_INTERNAL origin=do_election_check ]
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Election Timeout (I_ELECTION_DC:120000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: PEngine Recheck Timer (I_PE_CALC:900000ms) already
>> stopped
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_TE_START
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_te_control:
>> The
>> > transitioner is already active
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_PE_START
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: info: start_subsystem:
>> > Starting sub-system "pengine"
>> > Feb 3 07:02:50 vsa-0000004dc-vc-1 crmd: [1073]: WARN: start_subsystem:
>> > Client pengine already running as pid 1317
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:51 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:52 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:53 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > hb_send_local_status() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: PID 1023:
>> > Sending local status curnode = 638e58 status: active
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-1]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*hb_send_local_status*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-1) for
>> > master...
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > init_client_ipc_comms_nodispatch: Attempting to talk on:
>> > /var/run/crm/pengine
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 pengine: [1317]: debug: debug3:
>> > pe_client_connect: Invoked
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > parse_local_options: Processing master cib_slave_all op locally from
>> crmd
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: adjusted rcvbuf
>> size
>> > to 524288
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 pengine: [1317]: debug: adjusted
>> rcvbuf
>> > size to 1048576
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: adjusted sndbuf
>> size
>> > to 524288
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 pengine: [1317]: debug: adjusted
>> sndbuf
>> > size to 1048576
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_readwrite: Processing "cib_slave_all" event
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > init_client_ipc_comms_nodispatch: Processing of /var/run/crm/pengine
>> > complete
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 pengine: [1317]: debug:
>> > G_main_IPC_Channel_constructor(sock=7,7)
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > read_child_dispatch() {
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: info:
>> cib_process_readwrite:
>> > We are now in R/O mode
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug:
>> > G_main_IPC_Channel_constructor(sock=16,16)
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug: Packet
>> > authenticated
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: info:
>> cib_process_request:
>> > Operation complete: op cib_slave_all for section 'all'
>> > (origin=local/crmd/14, version=1.2.0): ok (rc=0)
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TIMER_STOP
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > process_clustermsg: node [vsa-0000004dc-vc-0]
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > cib_process_request: processing response cases
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Election Trigger (I_DC_TIMEOUT:5000ms) already stopped
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 heartbeat: [1023]: debug:
>> > }/*read_child_dispatch*/;
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > do_local_notify: Performing notification
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_INTEGRATE_TIMER_START
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > do_local_notify: Sending callback to request originator
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: crm_timer_start:
>> > Started Integration Timer (I_INTEGRATED:180000ms), src=26
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > do_local_notify: Sending an a-sync response to crmd
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_FINALIZE_TIMER_STOP
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > send_via_callback_channel: Delivering msg 0x805700 to client
>> > aa13a017-01bf-4589-af6c-084cec13f6fa
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug2:
>> > crm_timer_stop: Finalization Timer (I_ELECTION:1800000ms) already
>> stopped
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > send_via_callback_channel: Delivering reply to client
>> > aa13a017-01bf-4589-af6c-084cec13f6fa (cib_callback)
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: do_fsa_action:
>> > actions:trace: #011// A_DC_TAKEOVER
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Completed slave update
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: info: do_dc_takeover:
>> > Taking over DC status for this partition
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_request: Processing local message (vsa-0000004dc-vc-1) for
>> > master...
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Sending cib_slave_all message to CIB service
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > parse_local_options: Processing locally scoped cib_master op from crmd
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Message sent
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug3:
>> > cib_process_request: Finished determining processing actions
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Async call, returning
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: debug: debug2:
>> > cib_process_readwrite: Processing "cib_master" event
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_client_set_master: Adding cib_scope_local to options
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 cib: [1069]: info:
>> cib_process_readwrite:
>> > We are now in R/W mode
>> > Feb 3 07:02:54 vsa-0000004dc-vc-1 crmd: [1073]: debug: debug3:
>> > cib_native_perform_op: Sending cib_master message to CIB service
>> >
>> > thanks
>> > Shyam
>> >
>> >
>> >
>> > On Fri, Feb 3, 2012 at 4:04 AM, Andrew Beekhof <andrew at beekhof.net>
>> wrote:
>> >>
>> >> On Fri, Feb 3, 2012 at 9:31 AM, Andrew Beekhof <andrew at beekhof.net>
>> wrote:
>> >> > On Thu, Feb 2, 2012 at 9:55 PM, Shyam <shyam.kaushik at gmail.com>
>> wrote:
>> >> >> Hi Andrew,
>> >> >>
>> >> >> Here is more logs covering a larger period that shows multiple of
>> this
>> >> >> election cycle. Please note that in the below case I had set
>> >> >> dc-deadtime to
>> >> >> 5secs & the I_DC_TIMEOUT pops up every 5 secs. I turned this
>> >> >> dc-deadtime to
>> >> >> 10secs & the long election cycle problem disappeared. It no longer
>> >> >> happens.
>> >> >> I suspect that before a single election cycle completes, the next
>> >> >> I_DC_TIMEOUT kicks-in. Could this be the reason?
>> >> >
>> >> > Yes. The question is why the cycle is taking so long :-/
>> >>
>> >> Could you reproduce with debug on please?
>> >> It would be nice to know what the cluster is doing for the 4 seconds
>> >> between these two messages:
>> >>
>> >> Jan 17 12:00:04 vsa-0000003ca-vc-0 crmd: [1120]: WARN:
>> >> start_subsystem: Client pengine already running as pid 4243
>> >> Jan 17 12:00:08 vsa-0000003ca-vc-0 crmd: [1120]: info: do_dc_takeover:
>> >> Taking over DC status for this partition
>> >>
>> >> What version of pacemaker is this btw?
>> >>
>> >> _______________________________________________
>> >> Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
>> >> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>> >>
>> >> Project Home: http://www.clusterlabs.org
>> >> Getting started:
>> http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
>> >> Bugs: http://bugs.clusterlabs.org
>> >
>> >
>> >
>> > _______________________________________________
>> > Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
>> > http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>> >
>> > Project Home: http://www.clusterlabs.org
>> > Getting started:
>> http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
>> > Bugs: http://bugs.clusterlabs.org
>> >
>>
>> _______________________________________________
>> Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
>> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>>
>> Project Home: http://www.clusterlabs.org
>> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
>> Bugs: http://bugs.clusterlabs.org
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clusterlabs.org/pipermail/pacemaker/attachments/20120216/945298f6/attachment.htm>
More information about the Pacemaker
mailing list