On 30/07/2013, at 1:40 AM, mike <[email protected]> wrote: > Hi guys, > > I've got a rather odd issue. We have a simple two node cluster running one > VIP and mysql. Pretty sure I could create this cluster in my sleep. Anyway, > the cluster has been up and running for months with no issues at all. Last > night we had to shut down both nodes. On the primary node on startup for some > odd reason a config file got changed and the VIP came up when the server > booted. When operations tried to start HA it crapped out. They did get the > cluster going on the backup node so we're in business on one node. > > Looking this morning I could see the error where HA complained about the VIP > existing on both nodes.
I see errors about mysql being started on both nodes... > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: ERROR: > native_add_running: Resource lsb::mysqld:mysql appears to be active on 2 > nodes. Did you fix that too? > I checked the ifconfig file and sure enough the VIP was configured to come > up. No problem. I removed it and fired it up the node thinking it would join > the cluster. Nope. It erred out again. I checked the HA configs (cib.xml, > cib.xml.sig, ha.cf, authkeys) and made sure they were all identical on both > nodes. Below you will find a log snapshot of one attempted startup. > > Anyone got any ideas what's going on here? If I look at crm_mon I can > actually see the node join the cluster then it drops. > > Jul 29 14:41:10 DBSUAT1B.intranet.home.com cib: [2652]: info: cib_stats: > Processed 51 operations (5294.00us average, 0% utilization) in the last 10min > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Heartbeat > restart on node dbsuat1a.intranet.home.com > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Link > dbsuat1a.intranet.home.com:hsi0 up. > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Status > update for node dbsuat1a.intranet.home.com: status init > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Link > dbsuat1a.intranet.home.com:eth0 up. > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Status > update for node dbsuat1a.intranet.home.com: status up > Jul 29 14:45:54 DBSUAT1B.intranet.home.com crmd: [2656]: notice: > crmd_ha_status_callback: Status update: Node dbsuat1a.intranet.home.com now > has status [init] (DC=true) > Jul 29 14:45:54 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crm_update_peer_proc: dbsuat1a.intranet.home.com.ais is now online > Jul 29 14:45:54 DBSUAT1B.intranet.home.com crmd: [2656]: notice: > crmd_ha_status_callback: Status update: Node dbsuat1a.intranet.home.com now > has status [up] (DC=true) > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: all > clients are now paused > Jul 29 14:45:54 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Status > update for node dbsuat1a.intranet.home.com: status active > Jul 29 14:45:54 DBSUAT1B.intranet.home.com crmd: [2656]: notice: > crmd_ha_status_callback: Status update: Node dbsuat1a.intranet.home.com now > has status [active] (DC=true) > Jul 29 14:45:55 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_client_status_callback: Status update: Client > dbsuat1a.intranet.home.com/cib now has status [join] > Jul 29 14:45:59 DBSUAT1B.intranet.home.com heartbeat: [2636]: WARN: 1 lost > packet(s) for [dbsuat1a.intranet.home.com] [16:18] > Jul 29 14:45:59 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: No pkts > missing from dbsuat1a.intranet.home.com! > Jul 29 14:45:59 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: all > clients are now resumed > Jul 29 14:45:59 DBSUAT1B.intranet.home.com crmd: [2656]: notice: > crmd_client_status_callback: Status update: Client > dbsuat1a.intranet.home.com/crmd now has status [online] (DC=true) > Jul 29 14:46:00 DBSUAT1B.intranet.home.com heartbeat: [2636]: WARN: 1 lost > packet(s) for [dbsuat1a.intranet.home.com] [21:23] > Jul 29 14:46:00 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: No pkts > missing from dbsuat1a.intranet.home.com! > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: Got an event OC_EV_MS_INVALID from ccm > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: no mbr_track info > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: Got an event OC_EV_MS_INVALID from ccm > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: no mbr_track info > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: instance=10, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, > old_idx=4 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=10) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: NEW MEMBERSHIP: trans=10, nodes=2, new=1, lost=0 n_idx=0, > new_idx=2, old_idx=4 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: CURRENT: dbsuat1b.intranet.home.com [nodeid=1, born=1] > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: CURRENT: dbsuat1a.intranet.home.com [nodeid=0, born=10] > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: NEW: dbsuat1a.intranet.home.com [nodeid=0, born=10] > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ais_status_callback: status: dbsuat1a.intranet.home.com is now member (was > lost) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crm_update_peer: Node dbsuat1a.intranet.home.com: id=0 state=member (new) > addr=(null) votes=-1 born=10 seen=10 proc=00000000000000000000000000000202 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: instance=10, nodes=2, new=1, lost=0, n_idx=0, new_idx=2, > old_idx=4 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > populate_cib_nodes_ha: Requesting the list of configured nodes > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_ccm_msg_callback: Processing CCM event=NEW MEMBERSHIP (id=10) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > crm_update_peer: Node dbsuat1a.intranet.home.com: id=0 state=member (new) > addr=(null) votes=-1 born=10 seen=10 proc=00000000000000000000000000000302 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1a.intranet.home.com']/lrm (origin=local/crmd/176, > version=0.253.83): ok (rc=0) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1a.intranet.home.com']/transient_attributes > (origin=local/crmd/177, version=0.253.84): ok (rc=0) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com ccm: [2651]: WARN: > ccm_state_joined: received message with unknown cookie, just dropping > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: te_update_diff:267 - Triggered transition abort > (complete=1, tag=lrm_rsc_op, id=ip_mysql_monitor_0, > magic=0:7;7:23:7:c1031535-356b-4af4-92de-ef946f521cdf, cib=0.253.83) : > Resource op removal > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > erase_xpath_callback: Deletion of > "//node_state[@uname='dbsuat1a.intranet.home.com']/lrm": ok (rc=0) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: te_update_diff:157 - Triggered transition abort > (complete=1, tag=transient_attributes, > id=db80324b-c9de-4995-a66a-eedf93abb42c, magic=NA, cib=0.253.84) : Transient > attribute: removal > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > erase_xpath_callback: Deletion of > "//node_state[@uname='dbsuat1a.intranet.home.com']/transient_attributes": ok > (rc=0) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ > input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ] > Jul 29 14:46:01 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section nodes > (origin=local/crmd/178, version=0.253.84): ok (rc=0) > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: Membership changed: 8 -> 10 - join restart > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_pe_invoke: > Query 180: Requesting the current CIB: S_POLICY_ENGINE > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_POLICY_ENGINE -> S_INTEGRATION [ > input=I_NODE_JOIN cause=C_FSA_INTERNAL origin=do_state_transition ] > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: update_dc: > Unset DC dbsuat1b.intranet.home.com > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > join_make_offer: Making join offers based on membership 10 > Jul 29 14:46:01 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_offer_all: join-9: Waiting on 2 outstanding join acks > Jul 29 14:46:02 DBSUAT1B.intranet.home.com crmd: [2656]: info: update_dc: Set > DC to dbsuat1b.intranet.home.com (3.0.1) > Jul 29 14:46:03 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_sync_one for section 'all' > (origin=dbsuat1a.intranet.home.com/dbsuat1a.intranet.home.com/(null), > version=0.253.85): ok (rc=0) > Jul 29 14:46:03 DBSUAT1B.intranet.home.com crmd: [2656]: info: update_dc: > Unset DC dbsuat1b.intranet.home.com > Jul 29 14:46:03 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_offer_all: A new node joined the cluster > Jul 29 14:46:03 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_offer_all: join-10: Waiting on 2 outstanding join acks > Jul 29 14:46:03 DBSUAT1B.intranet.home.com crmd: [2656]: info: update_dc: Set > DC to dbsuat1b.intranet.home.com (3.0.1) > Jul 29 14:46:04 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_INTEGRATION -> S_FINALIZE_JOIN [ > input=I_INTEGRATED cause=C_FSA_INTERNAL origin=check_join_state ] > Jul 29 14:46:04 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: All 2 cluster nodes responded to the join offer. > Jul 29 14:46:04 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_finalize: join-10: Syncing the CIB from dbsuat1b.intranet.home.com > to the rest of the cluster > Jul 29 14:46:04 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_sync for section 'all' > (origin=local/crmd/183, version=0.253.85): ok (rc=0) > Jul 29 14:46:04 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section nodes > (origin=local/crmd/184, version=0.253.85): ok (rc=0) > Jul 29 14:46:04 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section nodes > (origin=local/crmd/185, version=0.253.85): ok (rc=0) > Jul 29 14:46:04 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_ack: join-10: Updating node state to member for > dbsuat1b.intranet.home.com > Jul 29 14:46:04 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1b.intranet.home.com']/lrm (origin=local/crmd/186, > version=0.253.86): ok (rc=0) > Jul 29 14:46:04 DBSUAT1B.intranet.home.com crmd: [2656]: info: > erase_xpath_callback: Deletion of > "//node_state[@uname='dbsuat1b.intranet.home.com']/lrm": ok (rc=0) > Jul 29 14:46:05 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_ha_callback: flush message from dbsuat1a.intranet.home.com > Jul 29 14:46:05 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_ack: join-10: Updating node state to member for > dbsuat1a.intranet.home.com > Jul 29 14:46:05 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1a.intranet.home.com']/transient_attributes > (origin=dbsuat1a.intranet.home.com/crmd/7, version=0.253.87): ok (rc=0) > Jul 29 14:46:05 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1a.intranet.home.com']/lrm > (origin=dbsuat1a.intranet.home.com/crmd/8, version=0.253.87): ok (rc=0) > Jul 29 14:46:05 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_delete for section > //node_state[@uname='dbsuat1a.intranet.home.com']/lrm (origin=local/crmd/188, > version=0.253.87): ok (rc=0) > Jul 29 14:46:05 DBSUAT1B.intranet.home.com crmd: [2656]: info: > erase_xpath_callback: Deletion of > "//node_state[@uname='dbsuat1a.intranet.home.com']/lrm": ok (rc=0) > Jul 29 14:46:05 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ > input=I_FINALIZED cause=C_FSA_INTERNAL origin=check_join_state ] > Jul 29 14:46:05 DBSUAT1B.intranet.home.com crmd: [2656]: info: > populate_cib_nodes_ha: Requesting the list of configured nodes > Jul 29 14:46:05 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_ha_callback: flush message from dbsuat1a.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: All 2 cluster nodes are eligible to run resources. > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_dc_join_final: Ensuring DC, quorum and node attributes are up-to-date > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crm_update_quorum: Updating quorum status to true (call=192) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_local_callback: Sending full refresh (origin=crmd) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_trigger_update: Sending flush op to all hosts for: probe_complete (true) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section nodes > (origin=local/crmd/190, version=0.253.88): ok (rc=0) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: do_te_invoke:191 - Triggered transition abort > (complete=1) : Peer Cancelled > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_pe_invoke: > Query 193: Requesting the current CIB: S_POLICY_ENGINE > Jul 29 14:46:06 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section cib > (origin=local/crmd/192, version=0.253.88): ok (rc=0) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1375109166-134, > seq=10, quorate=1 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_trigger_update: Sending flush op to all hosts for: terminate (<null>) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_trigger_update: Sending flush op to all hosts for: shutdown (<null>) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_config: On loss of CCM Quorum: Ignore > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for ip_mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1b.intranet.home.com is online > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1a.intranet.home.com is online > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > group_print: Resource Group: mysql-clu > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: mysql (lsb:mysqld): Started > dbsuat1b.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: ip_mysql (ocf::heartbeat:IPaddr2): Started > dbsuat1b.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Leave resource mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Leave resource ip_mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:06 DBSUAT1B.intranet.home.com pengine: [2663]: info: > process_pe_message: Transition 27: PEngine Input stored in: > /usr/var/lib/pengine/pe-input-29.bz2 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE > [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: unpack_graph: > Unpacked transition 27: 4 actions in 4 synapses > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_te_invoke: > Processing graph 27 (ref=pe_calc-dc-1375109166-134) derived from > /usr/var/lib/pengine/pe-input-29.bz2 > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 6: monitor mysql_monitor_0 on > dbsuat1a.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 7: monitor ip_mysql_monitor_0 on > dbsuat1a.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_ha_callback: flush message from dbsuat1b.intranet.home.com > Jul 29 14:46:06 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_ha_callback: flush message from dbsuat1b.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action ip_mysql_monitor_0 (7) confirmed on > dbsuat1a.intranet.home.com (rc=0) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: WARN: > status_from_rc: Action 6 (mysql_monitor_0) on dbsuat1a.intranet.home.com > failed (target: 7 vs. rc: 0): Error > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: match_graph_event:272 - Triggered transition abort > (complete=0, tag=lrm_rsc_op, id=mysql_monitor_0, > magic=0:0;6:27:7:c1031535-356b-4af4-92de-ef946f521cdf, cib=0.253.90) : Event > failed > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > update_abort_priority: Abort priority upgraded from 0 to 1 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > update_abort_priority: Abort action done superceeded by restart > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action mysql_monitor_0 (6) confirmed on > dbsuat1a.intranet.home.com (rc=4) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 5: probe_complete probe_complete on > dbsuat1a.intranet.home.com - no waiting > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: run_graph: > ==================================================== > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: notice: run_graph: > Transition 27 (Complete=3, Pending=0, Fired=0, Skipped=1, Incomplete=0, > Source=/usr/var/lib/pengine/pe-input-29.bz2): Stopped > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_graph_trigger: Transition 27 is now complete > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE > [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ] > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: All 2 cluster nodes are eligible to run resources. > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_pe_invoke: > Query 194: Requesting the current CIB: S_POLICY_ENGINE > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1375109167-138, > seq=10, quorate=1 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_config: On loss of CCM Quorum: Ignore > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for ip_mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1b.intranet.home.com is online > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1a.intranet.home.com is online > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_rsc_op: Operation mysql_monitor_0 found resource mysql active on > dbsuat1a.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: ERROR: > native_add_running: Resource lsb::mysqld:mysql appears to be active on 2 > nodes. > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: WARN: See > http://clusterlabs.org/wiki/FAQ#Resource_is_Too_Active for more information. > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > group_print: Resource Group: mysql-clu > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: mysql (lsb:mysqld) Started > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: 0 : dbsuat1b.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: 1 : dbsuat1a.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: ip_mysql (ocf::heartbeat:IPaddr2): Started > dbsuat1b.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: WARN: > native_create_actions: Attempting recovery of resource mysql > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > RecurringOp: Start recurring monitor (60s) for mysql on > dbsuat1b.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Restart resource mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Restart resource ip_mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com pengine: [2663]: ERROR: > process_pe_message: Transition 28: ERRORs found during PE processing. PEngine > Input stored in: /usr/var/lib/pengine/pe-error-10.bz2 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE > [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: unpack_graph: > Unpacked transition 28: 12 actions in 12 synapses > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_te_invoke: > Processing graph 28 (ref=pe_calc-dc-1375109167-138) derived from > /usr/var/lib/pengine/pe-error-10.bz2 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_pseudo_action: Pseudo action 13 fired and confirmed > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 9: stop ip_mysql_stop_0 on > dbsuat1b.intranet.home.com (local) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_lrm_rsc_op: > Performing key=9:28:0:c1031535-356b-4af4-92de-ef946f521cdf op=ip_mysql_stop_0 > ) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com lrmd: [2653]: info: > rsc:ip_mysql:28: stop > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 5: probe_complete probe_complete on > dbsuat1a.intranet.home.com - no waiting > IPaddr2[18426]: 2013/07/29_14:46:07 INFO: IP status = ok, IP_CIP= > IPaddr2[18426]: 2013/07/29_14:46:07 INFO: ip -f inet addr delete > 172.28.185.48/24 dev eth0 > IPaddr2[18426]: 2013/07/29_14:46:07 INFO: ip -o -f inet addr show eth0 > Jul 29 14:46:07 DBSUAT1B.intranet.home.com lrmd: [2653]: info: Managed > ip_mysql:stop process 18426 exited with return code 0. > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation ip_mysql_stop_0 (call=28, rc=0, > cib-update=195, confirmed=true) ok > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action ip_mysql_stop_0 (9) confirmed on > dbsuat1b.intranet.home.com (rc=0) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 6: stop mysql_stop_0 on > dbsuat1b.intranet.home.com (local) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_lrm_rsc_op: > Performing key=6:28:0:c1031535-356b-4af4-92de-ef946f521cdf op=mysql_stop_0 ) > Jul 29 14:46:07 DBSUAT1B.intranet.home.com lrmd: [2653]: info: rsc:mysql:29: > stop > Jul 29 14:46:07 DBSUAT1B.intranet.home.com lrmd: [18474]: WARN: For LSB init > script, no additional parameters are needed. > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 7: stop mysql_stop_0 on > dbsuat1a.intranet.home.com > Jul 29 14:46:07 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation mysql_monitor_60000 (call=26, status=1, > cib-update=0, confirmed=true) Cancelled > Jul 29 14:46:08 DBSUAT1B.intranet.home.com attrd: [2655]: info: > attrd_ha_callback: flush message from dbsuat1a.intranet.home.com > Jul 29 14:46:08 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: te_update_diff:146 - Triggered transition abort > (complete=0, tag=transient_attributes, > id=db80324b-c9de-4995-a66a-eedf93abb42c, magic=NA, cib=0.253.92) : Transient > attribute: update > Jul 29 14:46:08 DBSUAT1B.intranet.home.com crmd: [2656]: info: > update_abort_priority: Abort priority upgraded from 0 to 1000000 > Jul 29 14:46:08 DBSUAT1B.intranet.home.com crmd: [2656]: info: > update_abort_priority: Abort action done superceeded by restart > Jul 29 14:46:09 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action mysql_stop_0 (7) confirmed on > dbsuat1a.intranet.home.com (rc=0) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com lrmd: [2653]: info: RA output: > (mysql:stop:stdout) Mon Jul 29 14:46:16 GMT 2013 ##### MySQL stop (#3 of 3) > on DBSUAT1B.intranet.home.com --> SUCCESS rc=0 ##### > > Jul 29 14:46:16 DBSUAT1B.intranet.home.com lrmd: [2653]: info: Managed > mysql:stop process 18474 exited with return code 0. > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation mysql_stop_0 (call=29, rc=0, cib-update=196, > confirmed=true) ok > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action mysql_stop_0 (6) confirmed on > dbsuat1b.intranet.home.com (rc=0) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: run_graph: > ==================================================== > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: notice: run_graph: > Transition 28 (Complete=5, Pending=0, Fired=0, Skipped=7, Incomplete=0, > Source=/usr/var/lib/pengine/pe-error-10.bz2): Stopped > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_graph_trigger: Transition 28 is now complete > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE > [ input=I_PE_CALC cause=C_FSA_INTERNAL origin=notify_crmd ] > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: All 2 cluster nodes are eligible to run resources. > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_pe_invoke: > Query 197: Requesting the current CIB: S_POLICY_ENGINE > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1375109176-143, > seq=10, quorate=1 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_config: On loss of CCM Quorum: Ignore > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for ip_mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1b.intranet.home.com is online > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1a.intranet.home.com is online > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_rsc_op: Operation mysql_monitor_0 found resource mysql active on > dbsuat1a.intranet.home.com > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > group_print: Resource Group: mysql-clu > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: mysql (lsb:mysqld): Stopped > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: ip_mysql (ocf::heartbeat:IPaddr2): Stopped > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > RecurringOp: Start recurring monitor (60s) for mysql on > dbsuat1b.intranet.home.com > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Start mysql (dbsuat1b.intranet.home.com) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Start ip_mysql (dbsuat1b.intranet.home.com) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com pengine: [2663]: info: > process_pe_message: Transition 29: PEngine Input stored in: > /usr/var/lib/pengine/pe-input-30.bz2 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE > [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: unpack_graph: > Unpacked transition 29: 5 actions in 5 synapses > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_te_invoke: > Processing graph 29 (ref=pe_calc-dc-1375109176-143) derived from > /usr/var/lib/pengine/pe-input-30.bz2 > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_pseudo_action: Pseudo action 8 fired and confirmed > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 5: start mysql_start_0 on > dbsuat1b.intranet.home.com (local) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_lrm_rsc_op: > Performing key=5:29:0:c1031535-356b-4af4-92de-ef946f521cdf op=mysql_start_0 ) > Jul 29 14:46:16 DBSUAT1B.intranet.home.com lrmd: [2653]: info: rsc:mysql:30: > start > Jul 29 14:46:16 DBSUAT1B.intranet.home.com lrmd: [18549]: WARN: For LSB init > script, no additional parameters are needed. > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: RA output: > (mysql:start:stdout) Mon Jul 29 14:46:21 GMT 2013 ##### MySQL start #4 of 4 > on DBSUAT1B.intranet.home.com -> SUCCESS rc=0 ##### > > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: Managed > mysql:start process 18549 exited with return code 0. > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation mysql_start_0 (call=30, rc=0, > cib-update=198, confirmed=true) ok > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action mysql_start_0 (5) confirmed on > dbsuat1b.intranet.home.com (rc=0) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 6: monitor mysql_monitor_60000 on > dbsuat1b.intranet.home.com (local) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_lrm_rsc_op: > Performing key=6:29:0:c1031535-356b-4af4-92de-ef946f521cdf > op=mysql_monitor_60000 ) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: rsc:mysql:31: > monitor > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_rsc_command: Initiating action 7: start ip_mysql_start_0 on > dbsuat1b.intranet.home.com (local) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_lrm_rsc_op: > Performing key=7:29:0:c1031535-356b-4af4-92de-ef946f521cdf > op=ip_mysql_start_0 ) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: > rsc:ip_mysql:32: start > IPaddr2[19757]: 2013/07/29_14:46:21 INFO: ip -f inet addr add > 172.28.185.48/24 brd 172.28.185.255 dev eth0 > IPaddr2[19757]: 2013/07/29_14:46:21 INFO: ip link set eth0 up > IPaddr2[19757]: 2013/07/29_14:46:21 INFO: /usr/lib64/heartbeat/send_arp -i > 200 -r 5 -p /usr/var/run/heartbeat/rsctmp/send_arp/send_arp-172.28.185.48 > eth0 172.28.185.48 auto not_used not_used > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: Managed > ip_mysql:start process 19757 exited with return code 0. > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation ip_mysql_start_0 (call=32, rc=0, > cib-update=199, confirmed=true) ok > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action ip_mysql_start_0 (7) confirmed on > dbsuat1b.intranet.home.com (rc=0) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_pseudo_action: Pseudo action 9 fired and confirmed > Jul 29 14:46:21 DBSUAT1B.intranet.home.com lrmd: [2653]: info: Managed > mysql:monitor process 19751 exited with return code 0. > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > process_lrm_event: LRM operation mysql_monitor_60000 (call=31, rc=0, > cib-update=200, confirmed=false) ok > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > match_graph_event: Action mysql_monitor_60000 (6) confirmed on > dbsuat1b.intranet.home.com (rc=0) > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: run_graph: > ==================================================== > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: notice: run_graph: > Transition 29 (Complete=5, Pending=0, Fired=0, Skipped=0, Incomplete=0, > Source=/usr/var/lib/pengine/pe-input-30.bz2): Complete > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_graph_trigger: Transition 29 is now complete > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: notify_crmd: > Transition 29 status: done - <null> > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ > input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ] > Jul 29 14:46:21 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: Starting PEngine Recheck Timer > Jul 29 14:46:25 DBSUAT1B.intranet.home.com lrmd: [2653]: info: RA output: > (ip_mysql:start:stderr) ARPING 172.28.185.48 from 172.28.185.48 eth0 > Sent 5 probes (5 broadcast(s)) > Received 0 response(s) > > Jul 29 14:46:27 DBSUAT1B.intranet.home.com heartbeat: [2636]: WARN: node > dbsuat1a.intranet.home.com: is dead > Jul 29 14:46:27 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Link > dbsuat1a.intranet.home.com:hsi0 dead. > Jul 29 14:46:27 DBSUAT1B.intranet.home.com heartbeat: [2636]: info: Link > dbsuat1a.intranet.home.com:eth0 dead. > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: notice: > crmd_ha_status_callback: Status update: Node dbsuat1a.intranet.home.com now > has status [dead] (DC=true) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crm_update_peer_proc: dbsuat1a.intranet.home.com.ais is now offline > Jul 29 14:46:27 DBSUAT1B.intranet.home.com ccm: [2651]: info: Break tie for 2 > nodes cluster > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: WARN: > match_down_event: No match for shutdown action on > db80324b-c9de-4995-a66a-eedf93abb42c > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_update_diff: Stonith/shutdown of db80324b-c9de-4995-a66a-eedf93abb42c not > matched > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > abort_transition_graph: te_update_diff:191 - Triggered transition abort > (complete=1, tag=node_state, id=db80324b-c9de-4995-a66a-eedf93abb42c, > magic=NA, cib=0.253.98) : Node failure > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_IDLE -> S_POLICY_ENGINE [ > input=I_PE_CALC cause=C_FSA_INTERNAL origin=abort_transition_graph ] > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: All 2 cluster nodes are eligible to run resources. > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_pe_invoke: > Query 202: Requesting the current CIB: S_POLICY_ENGINE > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: Got an event OC_EV_MS_INVALID from ccm > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_pe_invoke_callback: Invoking the PE: ref=pe_calc-dc-1375109187-147, > seq=10, quorate=1 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: no mbr_track info > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: Got an event OC_EV_MS_INVALID from ccm > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: no mbr_track info > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > mem_handle_event: instance=11, nodes=1, new=0, lost=1, n_idx=0, new_idx=1, > old_idx=3 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: Got an event OC_EV_MS_NEW_MEMBERSHIP from ccm > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_ccm_msg_callback: Processing CCM event=NEW MEMBERSHIP (id=11) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > mem_handle_event: instance=11, nodes=1, new=0, lost=1, n_idx=0, new_idx=1, > old_idx=3 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com cib: [2652]: info: > crm_update_peer: Node dbsuat1a.intranet.home.com: id=0 state=lost (new) > addr=(null) votes=-1 born=10 seen=10 proc=00000000000000000000000000000302 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crmd_ccm_msg_callback: Quorum (re)attained after event=NEW MEMBERSHIP (id=11) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: NEW MEMBERSHIP: trans=11, nodes=1, new=0, lost=1 n_idx=0, > new_idx=1, old_idx=3 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: CURRENT: dbsuat1b.intranet.home.com [nodeid=1, born=11] > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ccm_event_detail: LOST: dbsuat1a.intranet.home.com [nodeid=0, born=10] > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > ais_status_callback: status: dbsuat1a.intranet.home.com is now lost (was > member) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > crm_update_peer: Node dbsuat1a.intranet.home.com: id=0 state=lost (new) > addr=(null) votes=-1 born=10 seen=10 proc=00000000000000000000000000000200 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > erase_node_from_join: Removed node dbsuat1a.intranet.home.com from join > calculations: welcomed=0 itegrated=0 finalized=0 confirmed=1 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com crmd: [2656]: info: > populate_cib_nodes_ha: Requesting the list of configured nodes > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > unpack_config: On loss of CCM Quorum: Ignore > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > unpack_config: Node scores: 'red' = -INFINITY, 'yellow' = 0, 'green' = 0 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql-clu of 11 based on > a stickiness of 1000000/100000 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > common_unpack: Calculated a migration threshold for ip_mysql of 11 based on a > stickiness of 1000000/100000 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > determine_online_status: Node dbsuat1b.intranet.home.com is online > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > group_print: Resource Group: mysql-clu > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: mysql (lsb:mysqld): Started > dbsuat1b.intranet.home.com > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > native_print: ip_mysql (ocf::heartbeat:IPaddr2): Started > dbsuat1b.intranet.home.com > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Leave resource mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: notice: > LogActions: Leave resource ip_mysql (Started dbsuat1b.intranet.home.com) > Jul 29 14:46:27 DBSUAT1B.intranet.home.com pengine: [2663]: info: > process_pe_message: Transition 30: PEngine Input stored in: > /usr/var/lib/pengine/pe-input-31.bz2 > Jul 29 14:46:27 DBSUAT1B.intranet.home.com ccm: [2651]: WARN: > ccm_state_joined: received message with unknown cookie, just dropping > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE > [ input=I_PE_SUCCESS cause=C_IPC_MESSAGE origin=handle_response ] > Jul 29 14:46:28 DBSUAT1B.intranet.home.com cib: [2652]: info: > cib_process_request: Operation complete: op cib_modify for section nodes > (origin=local/crmd/203, version=0.253.98): ok (rc=0) > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: unpack_graph: > Unpacked transition 30: 0 actions in 0 synapses > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: do_te_invoke: > Processing graph 30 (ref=pe_calc-dc-1375109187-147) derived from > /usr/var/lib/pengine/pe-input-31.bz2 > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: run_graph: > ==================================================== > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: notice: run_graph: > Transition 30 (Complete=0, Pending=0, Fired=0, Skipped=0, Incomplete=0, > Source=/usr/var/lib/pengine/pe-input-31.bz2): Complete > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: > te_graph_trigger: Transition 30 is now complete > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: notify_crmd: > Transition 30 status: done - <null> > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: State transition S_TRANSITION_ENGINE -> S_IDLE [ > input=I_TE_SUCCESS cause=C_FSA_INTERNAL origin=notify_crmd ] > Jul 29 14:46:28 DBSUAT1B.intranet.home.com crmd: [2656]: info: > do_state_transition: Starting PEngine Recheck Timer > _______________________________________________ > Linux-HA mailing list > [email protected] > http://lists.linux-ha.org/mailman/listinfo/linux-ha > See also: http://linux-ha.org/ReportingProblems _______________________________________________ Linux-HA mailing list [email protected] http://lists.linux-ha.org/mailman/listinfo/linux-ha See also: http://linux-ha.org/ReportingProblems
