Solved this one with some testing last night.
When I attempted to start up the backup node I noticed in the logs that
HA mentioned that mysql was already up on the backup node. This was
impossible because we use a shared filesystem and that filesystem was up
on the primary node with mysql running there. After I did a ps -ef |
grep mysql I saw there were no running processes so this lead to even
more confusion. How was HA seeing that mysql was up on the backup node
when it wasn't. Running /etc/init.d/mysqld status revealed the answer.
It actually returned SUCCESS and rc=0 meaning, it felt it was running
too. Looking further I could see where the status stanza was edited
months ago to remove all the actual instances of mysql and so it would
never return an error. Once I returned that stanza to its proper values,
all worked.
So long story short. With mysql running on the primary node and HA
thinking it was already up on the backup node when HA started there,
there was an obvious problem and HA killed the backup node 1 or 2
seconds after it joined the cluster. Good guy LinuxHA strikes again!
On 13-07-29 12:40 PM, mike 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 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
