[ClusterLabs] active/active OCFS2 interruption after bootup of failed node
lukas
lukas.kostyan at gmail.com
Fri May 8 11:39:53 EDT 2015
Hi,
have an active/active cluster with VIP/OCFS2/APACHE. Everything works
fine if one node is turned off - smooth switch of both IP's to active
node. The problem occurs as soon as the failed node boots up again. Both
clone (node1+node2) instances of all resource restart. So there is still
a short interruption. Why are the instances on node1 restarted as well?
Any suggestions how to prevent that?
node vm-1 \
attributes standby="off"
node vm-2 \
attributes standby="off"
primitive WebFS ocf:heartbeat:Filesystem \
params device="/dev/drbd/by-res/wwwdata"
directory="/var/www/html" fstype="ocfs2" \
op monitor interval="10"
primitive p_IP ocf:heartbeat:IPaddr2 \
params ip="192.168.122.200" nic="eth0"
clusterip_hash="sourceip-sourceport" \
op monitor interval="10s"
primitive p_apache ocf:heartbeat:apache \
params configfile="/etc/apache2/apache2.conf"
statusurl="http://localhost/server-status" \
op monitor interval="60" timeout="20" \
op start interval="0" timeout="40s" start-delay="0" \
meta is-managed="true"
primitive p_controld_dlm ocf:pacemaker:controld \
op monitor interval="120"
primitive p_drbd_wwwdata ocf:linbit:drbd \
params drbd_resource="wwwdata
op monitor interval="60s"
primitive
params hostlist="vm-1:N1"
hypervisor_uri="qemu+tcp://192.168.122.1/system"
pcmk_reboot_action="reset" \
op monitor interval="60
meta target-role="Started"
primitive p_fence_N2 stonith:external/libvirt \
params hostlist="vm-2:N2"
hypervisor_uri="qemu+tcp://192.168.122.1/system" pcmk_reboot_action="reset
op monitor interval="60"
primitive
op start interval="0" timeout="90" \
op stop interval="0" timeout="100
op monitor interval="10"
ms ms_drbd_ocfs2 p_drbd_wwwdata \
meta master-max="2" clone-max="2" notify="true"
clone cl_DLM p_controld_dlm \
meta globally-unique="false" interleave="true"
clone cl_IP p_IP \
meta globally-unique="true" clone-max="2" clone-node-max="2"
target-role="Started" interleave="true" \
params resource-stickiness="0"
clone cl_WebFS WebFS \
meta interleave="true" target-role="Started"
clone cl_Website p_apache
clone cl_o2cb p_o2cb \
meta globally-unique="false" interleave="true"
target-role="Started"
location l_fence_N1 p_fence_N1 -inf: vm-1
location l_fence_N2 p_fence_N2 -inf: vm-2
colocation c_fs_ip inf: cl_Website cl_WebFS
colocation c_o2cb_dlm inf: cl_o2cb cl_DLM
colocation c_o2cb_fs inf: cl_WebFS cl_o2cb
order o_ocfs2 inf: ms_drbd_ocfs2:promote cl_DLM:start cl_o2cb:start
cl_WebFS:start cl_Website cl_IP
property $id="cib-bootstrap-options" \
dc-version="1.1.7-ee0730e13d124c3d58f00016c3376a1de5323cff" \
cluster-infrastructure="openais" \
expected-quorum-votes="2" \
stonith-enabled="true" \
no-quorum-policy="ignore" \
last-lrm-refresh="1431076127"
rsc_defaults $id="rsc-options" \
resource-stickiness="200"
op_defaults $id="op-options" \
timeout="240s"
root at vm-1:~# tail -f /var/log/syslog
May 8 17:22:07 vm-1 IPaddr2[11583]: INFO: /usr/lib/heartbeat/send_arp
-i 200 -r 5 -p /var/run/resource-agents/send_arp-192.168.122.200 eth0
192.168.122.200 8bbd5f0b558f not_used not_used
May 8 17:22:07 vm-1 lrmd: [3008]: info: operation start[72] on p_IP:0
for client 3011: pid 11583 exited with return code 0
May 8 17:22:07 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_start_0 (call=72, rc=0, cib-update=211, confirmed=true) ok
May 8 17:22:07 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 80: monitor p_IP:0_monitor_10000 on vm-1 (local)
May 8 17:22:07 vm-1 lrmd: [3008]: info: rsc:p_IP:0 monitor[73] (pid 11684)
May 8 17:22:07 vm-1 lrmd: [3008]: info: operation monitor[73] on p_IP:0
for client 3011: pid 11684 exited with return code 0
May 8 17:22:07 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_monitor_10000 (call=73, rc=0, cib-update=212,
confirmed=false) ok
May 8 17:22:08 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 82: monitor p_IP:1_monitor_10000 on vm-2
May 8 17:22:08 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 14
(Complete=25, Pending=0, Fired=0, Skipped=0, Incomplete=0,
Source=/var/lib/pengine/pe-input-2179.bz2): Complete
May 8 17:22:08 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS
cause=C_FSA_INTERNAL origin=notify_crmd ]
May 8 17:22:27 vm-1 kernel: [ 534.940064] block drbd1: PingAck did not
arrive in time.
May 8 17:22:27 vm-1 kernel: [ 534.940238] block drbd1: peer( Primary
-> Unknown ) conn( Connected -> NetworkFailure ) pdsk( UpToDate ->
DUnknown )
May 8 17:22:27 vm-1 kernel: [ 534.940290] block drbd1: new current
UUID 1D8582A875D72EB5:098FF992CBAA32F1:248E28A17C6EBF3D:248D28A17C6EBF3D
May 8 17:22:27 vm-1 kernel: [ 534.942650] block drbd1: asender terminated
May 8 17:22:27 vm-1 kernel: [ 534.942654] block drbd1: Terminating
drbd1_asender
May 8 17:22:27 vm-1 kernel: [ 534.943633] block drbd1: Connection closed
May 8 17:22:27 vm-1 kernel: [ 534.943639] block drbd1: conn(
NetworkFailure -> Unconnected )
May 8 17:22:27 vm-1 kernel: [ 534.943643] block drbd1: receiver terminated
May 8 17:22:27 vm-1 kernel: [ 534.943645] block drbd1: Restarting
drbd1_receiver
May 8 17:22:27 vm-1 kernel: [ 534.943647] block drbd1: receiver
(re)started
May 8 17:22:27 vm-1 kernel: [ 534.943651] block drbd1: conn(
Unconnected -> WFConnection )
May 8 17:22:28 vm-1 corosync[2971]: [TOTEM ] A processor failed,
forming new configuration.
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] notice:
pcmk_peer_update: Transitional membership event on ring 7416: memb=1,
new=0, lost=1
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
memb: vm-1 2138745024
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
lost: vm-2 930785472
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] notice:
pcmk_peer_update: Stable membership event on ring 7416: memb=1, new=0,
lost=0
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
MEMB: vm-1 2138745024
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info:
ais_mark_unseen_peer_dead: Node vm-2 was not seen in the previous transition
May 8 17:22:32 vm-1 kernel: [ 540.163987] dlm: closing connection to
node 930785472
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info: update_member:
Node 930785472/vm-2 is now: lost
May 8 17:22:32 vm-1 corosync[2971]: [pcmk ] info:
send_member_notification: Sending membership update 7416 to 4 children
May 8 17:22:32 vm-1 corosync[2971]: [TOTEM ] A processor joined or
left the membership and a new membership was formed.
May 8 17:22:32 vm-1 crmd: [3011]: notice: ais_dispatch_message:
Membership 7416: quorum lost
May 8 17:22:32 vm-1 crmd: [3011]: info: ais_status_callback: status:
vm-2 is now lost (was member)
May 8 17:22:32 vm-1 crmd: [3011]: info: crm_update_peer: Node vm-2:
id=930785472 state=lost (new) addr=r(0) ip(192.168.122.183) votes=1
born=7412 seen=7412 proc=00000000000000000000000000111312
May 8 17:22:32 vm-1 ocfs2_controld: [3654]: notice:
ais_dispatch_message: Membership 7416: quorum lost
May 8 17:22:32 vm-1 cluster-dlm: [3605]: notice: ais_dispatch_message:
Membership 7416: quorum lost
May 8 17:22:32 vm-1 cib: [3006]: notice: ais_dispatch_message:
Membership 7416: quorum lost
May 8 17:22:32 vm-1 corosync[2971]: [CPG ] chosen downlist: sender
r(0) ip(192.168.122.127) ; members(old:2 left:1)
May 8 17:22:32 vm-1 ocfs2_controld: [3654]: info: crm_update_peer: Node
vm-2: id=930785472 state=lost (new) addr=r(0) ip(192.168.122.183)
votes=1 born=7412 seen=7412 proc=00000000000000000000000000111312
May 8 17:22:32 vm-1 cluster-dlm: [3605]: info: crm_update_peer: Node
vm-2: id=930785472 state=lost (new) addr=r(0) ip(192.168.122.183)
votes=1 born=7412 seen=7412 proc=00000000000000000000000000111312
May 8 17:22:32 vm-1 cib: [3006]: info: crm_update_peer: Node vm-2:
id=930785472 state=lost (new) addr=r(0) ip(192.168.122.183) votes=1
born=7412 seen=7412 proc=00000000000000000000000000111312
May 8 17:22:32 vm-1 corosync[2971]: [MAIN ] Completed service
synchronization, ready to provide service.
May 8 17:22:32 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/213,
version=0.593.601): ok (rc=0)
May 8 17:22:32 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section cib (origin=local/crmd/215,
version=0.593.603): ok (rc=0)
May 8 17:22:32 vm-1 crmd: [3011]: info: crmd_ais_dispatch: Setting
expected votes to 2
May 8 17:22:32 vm-1 crmd: [3011]: WARN: match_down_event: No match for
shutdown action on vm-2
May 8 17:22:32 vm-1 crmd: [3011]: info: te_update_diff:
Stonith/shutdown of vm-2 not matched
May 8 17:22:32 vm-1 crmd: [3011]: info: abort_transition_graph:
te_update_diff:234 - Triggered transition abort (complete=1,
tag=node_state, id=vm-2, magic=NA, cib=0.593.602) : Node failure
May 8 17:22:32 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_IDLE -> S_POLICY_ENGINE [ input=I_PE_CALC
cause=C_FSA_INTERNAL origin=abort_transition_graph ]
May 8 17:22:32 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section crm_config (origin=local/crmd/217,
version=0.593.604): ok (rc=0)
May 8 17:22:32 vm-1 pengine: [3010]: notice: unpack_config: On loss of
CCM Quorum: Ignore
May 8 17:22:32 vm-1 pengine: [3010]: WARN: pe_fence_node: Node vm-2
will be fenced because it is un-expectedly down
May 8 17:22:32 vm-1 pengine: [3010]: WARN: determine_online_status:
Node vm-2 is unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_fence_N1_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_drbd_wwwdata:1_demote_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_drbd_wwwdata:1_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_drbd_wwwdata:1_demote_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_drbd_wwwdata:1_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_controld_dlm:0_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_o2cb:0_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
WebFS:0_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_apache:1_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Action
p_IP:1_stop_0 on vm-2 is unrunnable (offline)
May 8 17:22:32 vm-1 pengine: [3010]: WARN: custom_action: Marking node
vm-2 unclean
May 8 17:22:32 vm-1 pengine: [3010]: WARN: stage6: Scheduling Node vm-2
for STONITH
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Stop
p_fence_N1#011(vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Demote
p_drbd_wwwdata:1#011(Master -> Stopped vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Stop
p_controld_dlm:0#011(vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Stop
p_o2cb:0#011(vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Stop
WebFS:0#011(vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Stop
p_apache:1#011(vm-2)
May 8 17:22:32 vm-1 pengine: [3010]: notice: LogActions: Move
p_IP:1#011(Started vm-2 -> vm-1)
May 8 17:22:32 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS
cause=C_IPC_MESSAGE origin=handle_response ]
May 8 17:22:32 vm-1 crmd: [3011]: info: do_te_invoke: Processing graph
15 (ref=pe_calc-dc-1431098552-227) derived from
/var/lib/pengine/pe-warn-694.bz2
May 8 17:22:32 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 99: notify p_drbd_wwwdata:0_pre_notify_demote_0 on vm-1 (local)
May 8 17:22:32 vm-1 lrmd: [3008]: info: rsc:p_drbd_wwwdata:0 notify[74]
(pid 11972)
May 8 17:22:32 vm-1 crmd: [3011]: notice: te_fence_node: Executing
reboot fencing operation (82) on vm-2 (timeout=60000)
May 8 17:22:32 vm-1 stonith-ng: [3007]: info:
initiate_remote_stonith_op: Initiating remote operation reboot for vm-2:
6b9a869c-b8c3-43fe-b8d0-362717852644
May 8 17:22:32 vm-1 stonith-ng: [3007]: info:
can_fence_host_with_device: p_fence_N2 can fence vm-2: dynamic-list
May 8 17:22:32 vm-1 stonith-ng: [3007]: info: call_remote_stonith:
Requesting that vm-1 perform op reboot vm-2
May 8 17:22:32 vm-1 stonith-ng: [3007]: info:
can_fence_host_with_device: p_fence_N2 can fence vm-2: dynamic-list
May 8 17:22:32 vm-1 stonith-ng: [3007]: info: stonith_fence: Found 1
matching devices for 'vm-2'
May 8 17:22:32 vm-1 stonith-ng: [3007]: info: stonith_command:
Processed st_fence from vm-1: rc=-1
May 8 17:22:32 vm-1 stonith-ng: [3007]: info: make_args: Substituting
action 'reset' for requested operation 'reboot'
May 8 17:22:32 vm-1 pengine: [3010]: WARN: process_pe_message:
Transition 15: WARNINGs found during PE processing. PEngine Input stored
in: /var/lib/pengine/pe-warn-694.bz2
May 8 17:22:32 vm-1 pengine: [3010]: notice: process_pe_message:
Configuration WARNINGs found during PE processing. Please run
"crm_verify -L" to identify issues.
May 8 17:22:32 vm-1 lrmd: [3008]: info: operation notify[74] on
p_drbd_wwwdata:0 for client 3011: pid 11972 exited with return code 0
May 8 17:22:32 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_drbd_wwwdata:0_notify_0 (call=74, rc=0, cib-update=0,
confirmed=true) ok
May 8 17:22:32 vm-1 external/libvirt[11993]: [12016]: notice: Domain N2
was stopped
May 8 17:22:35 vm-1 external/libvirt[11993]: [12025]: notice: Domain N2
was started
May 8 17:22:36 vm-1 stonith-ng: [3007]: notice: log_operation:
Operation 'reboot' [11973] (call 0 from
97c57579-f851-458e-8256-6c87e2308265) for host 'vm-2' with device
'p_fence_N2' returned: 0
May 8 17:22:36 vm-1 stonith-ng: [3007]: info: log_operation:
p_fence_N2: Performing: stonith -t external/libvirt -T reset vm-2
May 8 17:22:36 vm-1 stonith-ng: [3007]: info: log_operation:
p_fence_N2: success: vm-2 0
May 8 17:22:36 vm-1 stonith-ng: [3007]: notice: remote_op_done:
Operation reboot of vm-2 by vm-1 for
vm-1[97c57579-f851-458e-8256-6c87e2308265]: OK
May 8 17:22:36 vm-1 crmd: [3011]: info: tengine_stonith_callback:
StonithOp <st-reply st_origin="stonith_construct_async_reply"
t="stonith-ng" st_op="reboot"
st_remote_op="6b9a869c-b8c3-43fe-b8d0-362717852644"
st_clientid="97c57579-f851-458e-8256-6c87e2308265" st_target="vm-2"
st_device_action="st_fence" st_callid="0" st_callopt="0" st_rc="0"
st_output="Performing: stonith -t external/libvirt -T reset
vm-2#012success: vm-2 0#012" src="vm-1" seq="16" state="2" />
May 8 17:22:36 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-2']/lrm
May 8 17:22:36 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-2']/transient_attributes
May 8 17:22:36 vm-1 crmd: [3011]: notice: crmd_peer_update: Status
update: Client vm-2/crmd now has status [offline] (DC=true)
May 8 17:22:36 vm-1 crmd: [3011]: notice: tengine_stonith_notify: Peer
vm-2 was terminated (reboot) by vm-1 for vm-1: OK
(ref=6b9a869c-b8c3-43fe-b8d0-362717852644)
May 8 17:22:36 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_INTEGRATION [ input=I_NODE_JOIN
cause=C_FSA_INTERNAL origin=check_join_state ]
May 8 17:22:36 vm-1 crmd: [3011]: info: abort_transition_graph:
do_te_invoke:169 - Triggered transition abort (complete=0) : Peer Halt
May 8 17:22:36 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 15
(Complete=7, Pending=0, Fired=0, Skipped=22, Incomplete=15,
Source=/var/lib/pengine/pe-warn-694.bz2): Stopped
May 8 17:22:36 vm-1 crmd: [3011]: info: abort_transition_graph:
do_te_invoke:169 - Triggered transition abort (complete=1) : Peer Halt
May 8 17:22:36 vm-1 crmd: [3011]: info: join_make_offer: Making join
offers based on membership 7416
May 8 17:22:36 vm-1 crmd: [3011]: info: do_dc_join_offer_all: join-10:
Waiting on 1 outstanding join acks
May 8 17:22:36 vm-1 crmd: [3011]: info: update_dc: Set DC to vm-1 (3.0.6)
May 8 17:22:36 vm-1 crmd: [3011]: info: cib_fencing_updated: Fencing
update 219 for vm-2: complete
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section //node_state[@uname='vm-2']/lrm
(origin=local/crmd/220, version=0.593.606): ok (rc=0)
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section
//node_state[@uname='vm-2']/transient_attributes (origin=local/crmd/221,
version=0.593.607): ok (rc=0)
May 8 17:22:36 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED
cause=C_FSA_INTERNAL origin=check_join_state ]
May 8 17:22:36 vm-1 crmd: [3011]: info: do_dc_join_finalize: join-10:
Syncing the CIB from vm-1 to the rest of the cluster
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_sync for section 'all' (origin=local/crmd/224,
version=0.593.608): ok (rc=0)
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/225,
version=0.593.609): ok (rc=0)
May 8 17:22:36 vm-1 crmd: [3011]: info: do_dc_join_ack: join-10:
Updating node state to member for vm-1
May 8 17:22:36 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-1']/lrm
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section //node_state[@uname='vm-1']/lrm
(origin=local/crmd/226, version=0.593.610): ok (rc=0)
May 8 17:22:36 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED
cause=C_FSA_INTERNAL origin=check_join_state ]
May 8 17:22:36 vm-1 crmd: [3011]: info: abort_transition_graph:
do_te_invoke:162 - Triggered transition abort (complete=1) : Peer Cancelled
May 8 17:22:36 vm-1 attrd: [3009]: notice: attrd_local_callback:
Sending full refresh (origin=crmd)
May 8 17:22:36 vm-1 attrd: [3009]: notice: attrd_trigger_update:
Sending flush op to all hosts for: master-p_drbd_wwwdata:0 (10000)
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/228,
version=0.593.612): ok (rc=0)
May 8 17:22:36 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section cib (origin=local/crmd/230,
version=0.593.614): ok (rc=0)
May 8 17:22:36 vm-1 attrd: [3009]: notice: attrd_trigger_update:
Sending flush op to all hosts for: probe_complete (true)
May 8 17:22:36 vm-1 pengine: [3010]: notice: unpack_config: On loss of
CCM Quorum: Ignore
May 8 17:22:36 vm-1 pengine: [3010]: notice: LogActions: Start
p_IP:1#011(vm-1)
May 8 17:22:36 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS
cause=C_IPC_MESSAGE origin=handle_response ]
May 8 17:22:36 vm-1 crmd: [3011]: info: do_te_invoke: Processing graph
16 (ref=pe_calc-dc-1431098556-234) derived from
/var/lib/pengine/pe-input-2180.bz2
May 8 17:22:36 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 66: start p_IP:1_start_0 on vm-1 (local)
May 8 17:22:36 vm-1 lrmd: [3008]: info: rsc:p_IP:1 start[75] (pid 12069)
May 8 17:22:36 vm-1 pengine: [3010]: notice: process_pe_message:
Transition 16: PEngine Input stored in: /var/lib/pengine/pe-input-2180.bz2
May 8 17:22:36 vm-1 kernel: [ 544.194603] ocfs2: Begin replay journal
(node 930785472, slot 0) on device (147,1)
May 8 17:22:36 vm-1 IPaddr2[12069]: INFO: /usr/lib/heartbeat/send_arp
-i 200 -r 5 -p /var/run/resource-agents/send_arp-192.168.122.200 eth0
192.168.122.200 8bbd5f0b558f not_used not_used
May 8 17:22:36 vm-1 lrmd: [3008]: info: operation start[75] on p_IP:1
for client 3011: pid 12069 exited with return code 0
May 8 17:22:36 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:1_start_0 (call=75, rc=0, cib-update=232, confirmed=true) ok
May 8 17:22:36 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 67: monitor p_IP:1_monitor_10000 on vm-1 (local)
May 8 17:22:36 vm-1 lrmd: [3008]: info: rsc:p_IP:1 monitor[76] (pid 12124)
May 8 17:22:36 vm-1 lrmd: [3008]: info: operation monitor[76] on p_IP:1
for client 3011: pid 12124 exited with return code 0
May 8 17:22:36 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:1_monitor_10000 (call=76, rc=0, cib-update=233,
confirmed=false) ok
May 8 17:22:36 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 16
(Complete=4, Pending=0, Fired=0, Skipped=0, Incomplete=0,
Source=/var/lib/pengine/pe-input-2180.bz2): Complete
May 8 17:22:36 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS
cause=C_FSA_INTERNAL origin=notify_crmd ]
May 8 17:22:36 vm-1 kernel: [ 544.424174] ocfs2: End replay journal
(node 930785472, slot 0) on device (147,1)
May 8 17:22:36 vm-1 kernel: [ 544.424468] ocfs2: Beginning quota
recovery on device (147,1) for slot 0
May 8 17:22:36 vm-1 kernel: [ 544.424697] ocfs2: Finishing quota
recovery on device (147,1) for slot 0
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] notice:
pcmk_peer_update: Transitional membership event on ring 7420: memb=1,
new=0, lost=0
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
memb: vm-1 2138745024
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] notice:
pcmk_peer_update: Stable membership event on ring 7420: memb=2, new=1,
lost=0
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: update_member:
Node 930785472/vm-2 is now: member
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
NEW: vm-2 930785472
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
MEMB: vm-1 2138745024
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: pcmk_peer_update:
MEMB: vm-2 930785472
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info:
send_member_notification: Sending membership update 7420 to 4 children
May 8 17:22:46 vm-1 cib: [3006]: notice: ais_dispatch_message:
Membership 7420: quorum acquired
May 8 17:22:46 vm-1 ocfs2_controld: [3654]: notice:
ais_dispatch_message: Membership 7420: quorum acquired
May 8 17:22:46 vm-1 cib: [3006]: info: crm_update_peer: Node vm-2:
id=930785472 state=member (new) addr=r(0) ip(192.168.122.183) votes=1
born=7412 seen=7420 proc=00000000000000000000000000111312
May 8 17:22:46 vm-1 ocfs2_controld: [3654]: info: crm_update_peer: Node
vm-2: id=930785472 state=member (new) addr=r(0) ip(192.168.122.183)
votes=1 born=7412 seen=7420 proc=00000000000000000000000000111312
May 8 17:22:46 vm-1 crmd: [3011]: notice: ais_dispatch_message:
Membership 7420: quorum acquired
May 8 17:22:46 vm-1 cluster-dlm: [3605]: notice: ais_dispatch_message:
Membership 7420: quorum acquired
May 8 17:22:46 vm-1 corosync[2971]: [TOTEM ] A processor joined or
left the membership and a new membership was formed.
May 8 17:22:46 vm-1 crmd: [3011]: notice: crmd_peer_update: Status
update: Client vm-2/crmd now has status [online] (DC=true)
May 8 17:22:46 vm-1 cluster-dlm: [3605]: info: crm_update_peer: Node
vm-2: id=930785472 state=member (new) addr=r(0) ip(192.168.122.183)
votes=1 born=7412 seen=7420 proc=00000000000000000000000000111312
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info: update_member:
0x1c6a520 Node 930785472 (vm-2) born on: 7420
May 8 17:22:46 vm-1 corosync[2971]: [pcmk ] info:
send_member_notification: Sending membership update 7420 to 4 children
May 8 17:22:46 vm-1 ocfs2_controld: [3654]: info: ais_dispatch_message:
Membership 7420: quorum retained
May 8 17:22:46 vm-1 crmd: [3011]: info: ais_status_callback: status:
vm-2 is now member (was lost)
May 8 17:22:46 vm-1 cib: [3006]: info: ais_dispatch_message: Membership
7420: quorum retained
May 8 17:22:46 vm-1 cluster-dlm: [3605]: info: ais_dispatch_message:
Membership 7420: quorum retained
May 8 17:22:46 vm-1 crmd: [3011]: WARN: match_down_event: No match for
shutdown action on vm-2
May 8 17:22:46 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-2']/lrm
May 8 17:22:46 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-2']/transient_attributes
May 8 17:22:46 vm-1 crmd: [3011]: info: crm_update_peer: Node vm-2:
id=930785472 state=member (new) addr=r(0) ip(192.168.122.183) votes=1
born=7412 seen=7420 proc=00000000000000000000000000111312 (new)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section //node_state[@uname='vm-2']/lrm
(origin=local/crmd/235, version=0.593.620): ok (rc=0)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section
//node_state[@uname='vm-2']/transient_attributes (origin=local/crmd/236,
version=0.593.621): ok (rc=0)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/237,
version=0.593.622): ok (rc=0)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section cib (origin=local/crmd/239,
version=0.593.624): ok (rc=0)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_sync_one for section 'all' (origin=vm-2/vm-2/(null),
version=0.593.624): ok (rc=0)
May 8 17:22:46 vm-1 crmd: [3011]: info: crmd_ais_dispatch: Setting
expected votes to 2
May 8 17:22:46 vm-1 crmd: [3011]: info: ais_dispatch_message:
Membership 7420: quorum retained
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section crm_config (origin=local/crmd/241,
version=0.593.625): ok (rc=0)
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/242,
version=0.593.626): ok (rc=0)
May 8 17:22:46 vm-1 crmd: [3011]: info: crmd_ais_dispatch: Setting
expected votes to 2
May 8 17:22:46 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_IDLE -> S_INTEGRATION [ input=I_NODE_JOIN
cause=C_FSA_INTERNAL origin=crmd_peer_update ]
May 8 17:22:46 vm-1 crmd: [3011]: info: abort_transition_graph:
do_te_invoke:169 - Triggered transition abort (complete=1) : Peer Halt
May 8 17:22:46 vm-1 crmd: [3011]: info: join_make_offer: Making join
offers based on membership 7420
May 8 17:22:46 vm-1 crmd: [3011]: info: do_dc_join_offer_all: join-11:
Waiting on 2 outstanding join acks
May 8 17:22:46 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section crm_config (origin=local/crmd/245,
version=0.593.628): ok (rc=0)
May 8 17:22:46 vm-1 crmd: [3011]: info: update_dc: Set DC to vm-1 (3.0.6)
May 8 17:22:46 vm-1 corosync[2971]: [CPG ] chosen downlist: sender
r(0) ip(192.168.122.183) ; members(old:1 left:0)
May 8 17:22:46 vm-1 corosync[2971]: [MAIN ] Completed service
synchronization, ready to provide service.
May 8 17:22:47 vm-1 crmd: [3011]: info: do_dc_join_offer_all: A new
node joined the cluster
May 8 17:22:47 vm-1 crmd: [3011]: info: do_dc_join_offer_all: join-12:
Waiting on 2 outstanding join acks
May 8 17:22:47 vm-1 crmd: [3011]: info: update_dc: Set DC to vm-1 (3.0.6)
May 8 17:22:48 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_INTEGRATION -> S_FINALIZE_JOIN [ input=I_INTEGRATED
cause=C_FSA_INTERNAL origin=check_join_state ]
May 8 17:22:48 vm-1 crmd: [3011]: info: do_dc_join_finalize: join-12:
Syncing the CIB from vm-1 to the rest of the cluster
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_sync for section 'all' (origin=local/crmd/248,
version=0.593.628): ok (rc=0)
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/249,
version=0.593.629): ok (rc=0)
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/250,
version=0.593.630): ok (rc=0)
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section
//node_state[@uname='vm-2']/transient_attributes (origin=vm-2/crmd/6,
version=0.593.631): ok (rc=0)
May 8 17:22:48 vm-1 crmd: [3011]: info: do_dc_join_ack: join-12:
Updating node state to member for vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-2']/lrm
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section //node_state[@uname='vm-2']/lrm
(origin=local/crmd/251, version=0.593.632): ok (rc=0)
May 8 17:22:48 vm-1 crmd: [3011]: info: do_dc_join_ack: join-12:
Updating node state to member for vm-1
May 8 17:22:48 vm-1 crmd: [3011]: info: erase_status_tag: Deleting
xpath: //node_state[@uname='vm-1']/lrm
May 8 17:22:48 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_FINALIZE_JOIN -> S_POLICY_ENGINE [ input=I_FINALIZED
cause=C_FSA_INTERNAL origin=check_join_state ]
May 8 17:22:48 vm-1 crmd: [3011]: info: abort_transition_graph:
do_te_invoke:162 - Triggered transition abort (complete=1) : Peer Cancelled
May 8 17:22:48 vm-1 attrd: [3009]: notice: attrd_local_callback:
Sending full refresh (origin=crmd)
May 8 17:22:48 vm-1 attrd: [3009]: notice: attrd_trigger_update:
Sending flush op to all hosts for: master-p_drbd_wwwdata:0 (10000)
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section //node_state[@uname='vm-1']/lrm
(origin=local/crmd/253, version=0.593.634): ok (rc=0)
May 8 17:22:48 vm-1 crmd: [3011]: info: abort_transition_graph:
te_update_diff:320 - Triggered transition abort (complete=1,
tag=lrm_rsc_op, id=p_drbd_wwwdata:0_last_0,
magic=0:0;19:4:0:9ba781e6-a6db-4310-bddd-8740dea7b7d9, cib=0.593.634) :
Resource op removal
May 8 17:22:48 vm-1 crmd: [3011]: info: abort_transition_graph:
te_update_diff:276 - Triggered transition abort (complete=1, tag=diff,
id=(null), magic=NA, cib=0.593.635) : LRM Refresh
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section nodes (origin=local/crmd/255,
version=0.593.636): ok (rc=0)
May 8 17:22:48 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_modify for section cib (origin=local/crmd/257,
version=0.593.638): ok (rc=0)
May 8 17:22:48 vm-1 attrd: [3009]: notice: attrd_trigger_update:
Sending flush op to all hosts for: probe_complete (true)
May 8 17:22:48 vm-1 pengine: [3010]: notice: unpack_config: On loss of
CCM Quorum: Ignore
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
p_fence_N1#011(vm-2)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
p_drbd_wwwdata:1#011(vm-2)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
p_controld_dlm:0#011(vm-2 - blocked)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
p_o2cb:0#011(vm-2 - blocked)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
WebFS:0#011(vm-2 - blocked)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Restart
p_apache:0#011(Started vm-1)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Start
p_apache:1#011(vm-2)
May 8 17:22:48 vm-1 pengine: [3010]: notice: LogActions: Move
p_IP:1#011(Started vm-1 -> vm-2)
May 8 17:22:48 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS
cause=C_IPC_MESSAGE origin=handle_response ]
May 8 17:22:48 vm-1 crmd: [3011]: info: do_te_invoke: Processing graph
17 (ref=pe_calc-dc-1431098568-248) derived from
/var/lib/pengine/pe-input-2181.bz2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 12: monitor p_fence_N1_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 13: monitor p_fence_N2_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 14: monitor p_drbd_wwwdata:1_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 15: monitor p_controld_dlm:0_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 16: monitor p_o2cb:0_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 17: monitor WebFS:0_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 18: monitor p_apache:1_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 19: monitor p_IP:0_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 20: monitor p_IP:1_monitor_0 on vm-2
May 8 17:22:48 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 101: notify p_drbd_wwwdata:0_pre_notify_start_0 on vm-1 (local)
May 8 17:22:48 vm-1 lrmd: [3008]: info: rsc:p_drbd_wwwdata:0 notify[77]
(pid 12386)
May 8 17:22:48 vm-1 pengine: [3010]: notice: process_pe_message:
Transition 17: PEngine Input stored in: /var/lib/pengine/pe-input-2181.bz2
May 8 17:22:48 vm-1 lrmd: [3008]: info: RA output:
(p_drbd_wwwdata:0:notify:stdout)
May 8 17:22:48 vm-1 lrmd: [3008]: info: operation notify[77] on
p_drbd_wwwdata:0 for client 3011: pid 12386 exited with return code 0
May 8 17:22:48 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_drbd_wwwdata:0_notify_0 (call=77, rc=0, cib-update=0,
confirmed=true) ok
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 11: probe_complete probe_complete on vm-2 - no waiting
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 21: start p_fence_N1_start_0 on vm-2
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 29: start p_drbd_wwwdata:1_start_0 on vm-2
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 87: stop p_IP:0_stop_0 on vm-1 (local)
May 8 17:22:49 vm-1 lrmd: [3008]: info: cancel_op: operation
monitor[73] on p_IP:0 for client 3011, its parameters:
resource-stickiness=[0] CRM_meta_timeout=[240000]
CRM_meta_name=[monitor] crm_feature_set=[3.0.6] CRM_meta_notify=[false]
CRM_meta_clone_node_max=[2] CRM_meta_clone=[0]
clusterip_hash=[sourceip-sourceport] CRM_meta_clone_max=[2]
CRM_meta_interval=[10000] ip=[192.168.122.200] nic=[eth0]
CRM_meta_globally_unique=[true] cancelled
May 8 17:22:49 vm-1 lrmd: [3008]: info: rsc:p_IP:0 stop[78] (pid 12416)
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 89: stop p_IP:1_stop_0 on vm-1 (local)
May 8 17:22:49 vm-1 lrmd: [3008]: info: cancel_op: operation
monitor[76] on p_IP:1 for client 3011, its parameters:
resource-stickiness=[0] CRM_meta_timeout=[240000]
CRM_meta_name=[monitor] crm_feature_set=[3.0.6] CRM_meta_notify=[false]
CRM_meta_clone_node_max=[2] CRM_meta_clone=[1]
clusterip_hash=[sourceip-sourceport] CRM_meta_clone_max=[2]
CRM_meta_interval=[10000] ip=[192.168.122.200] nic=[eth0]
CRM_meta_globally_unique=[true] cancelled
May 8 17:22:49 vm-1 lrmd: [3008]: info: rsc:p_IP:1 stop[79] (pid 12417)
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_monitor_10000 (call=73, status=1, cib-update=0,
confirmed=true) Cancelled
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:1_monitor_10000 (call=76, status=1, cib-update=0,
confirmed=true) Cancelled
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 102: notify p_drbd_wwwdata:0_post_notify_start_0 on vm-1 (local)
May 8 17:22:49 vm-1 lrmd: [3008]: info: rsc:p_drbd_wwwdata:0 notify[80]
(pid 12542)
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 103: notify p_drbd_wwwdata:1_post_notify_start_0 on vm-2
May 8 17:22:49 vm-1 lrmd: [3008]: info: RA output:
(p_drbd_wwwdata:0:notify:stdout)
May 8 17:22:49 vm-1 lrmd: [3008]: info: operation notify[80] on
p_drbd_wwwdata:0 for client 3011: pid 12542 exited with return code 0
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_drbd_wwwdata:0_notify_0 (call=80, rc=0, cib-update=0,
confirmed=true) ok
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 30: monitor p_drbd_wwwdata:1_monitor_60000 on vm-2
May 8 17:22:49 vm-1 IPaddr2[12416]: INFO: Sleeping until
/var/run/resource-agents/IPaddr2-CIP-192.168.122.200 is released...
May 8 17:22:49 vm-1 IPaddr2[12417]: INFO: IP status = ok, IP_CIP=yes
May 8 17:22:49 vm-1 lrmd: [3008]: info: operation stop[79] on p_IP:1
for client 3011: pid 12417 exited with return code 0
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:1_stop_0 (call=79, rc=0, cib-update=261, confirmed=true) ok
May 8 17:22:49 vm-1 IPaddr2[12416]: INFO: IP status = ok, IP_CIP=yes
May 8 17:22:49 vm-1 IPaddr2[12416]: INFO: 192.168.122.200,
sourceip-sourceport
May 8 17:22:49 vm-1 IPaddr2[12416]: INFO: 1
May 8 17:22:49 vm-1 IPaddr2[12416]: INFO: 2
May 8 17:22:49 vm-1 lrmd: [3008]: info: RA output: (p_IP:0:stop:stderr)
iptables: No chain/target/match by that name.
May 8 17:22:49 vm-1 lrmd: [3008]: info: operation stop[78] on p_IP:0
for client 3011: pid 12416 exited with return code 0
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_stop_0 (call=78, rc=0, cib-update=262, confirmed=true) ok
May 8 17:22:49 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 79: stop p_apache:0_stop_0 on vm-1 (local)
May 8 17:22:49 vm-1 lrmd: [3008]: info: cancel_op: operation
monitor[71] on p_apache:0 for client 3011, its parameters:
CRM_meta_start_delay=[0] CRM_meta_timeout=[20000]
CRM_meta_name=[monitor] crm_feature_set=[3.0.6]
CRM_meta_clone_node_max=[1] configfile=[/etc/apache2/apache2.conf]
CRM_meta_clone=[0] CRM_meta_interval=[60000] CRM_meta_clone_max=[2]
CRM_meta_notify=[false] statusurl=[http://localhost/server-status]
CRM_meta_globally_unique=[false] cancelled
May 8 17:22:49 vm-1 lrmd: [3008]: info: rsc:p_apache:0 stop[81] (pid 12624)
May 8 17:22:49 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_monitor_60000 (call=71, status=1, cib-update=0,
confirmed=true) Cancelled
May 8 17:22:50 vm-1 kernel: [ 558.096196] block drbd1: Handshake
successful: Agreed network protocol version 96
May 8 17:22:50 vm-1 kernel: [ 558.096204] block drbd1: conn(
WFConnection -> WFReportParams )
May 8 17:22:50 vm-1 kernel: [ 558.096220] block drbd1: Starting
asender thread (from drbd1_receiver [3403])
May 8 17:22:50 vm-1 kernel: [ 558.097865] block drbd1:
data-integrity-alg: <not-used>
May 8 17:22:50 vm-1 kernel: [ 558.097901] block drbd1:
drbd_sync_handshake:
May 8 17:22:50 vm-1 kernel: [ 558.097913] block drbd1: self
1D8582A875D72EB5:098FF992CBAA32F1:248E28A17C6EBF3D:248D28A17C6EBF3D
bits:4 flags:0
May 8 17:22:50 vm-1 kernel: [ 558.097925] block drbd1: peer
098FF992CBAA32F0:0000000000000000:248E28A17C6EBF3C:248D28A17C6EBF3D
bits:3072 flags:2
May 8 17:22:50 vm-1 kernel: [ 558.097935] block drbd1:
uuid_compare()=1 by rule 70
May 8 17:22:50 vm-1 kernel: [ 558.097951] block drbd1: peer( Unknown
-> Secondary ) conn( WFReportParams -> WFBitMapS ) pdsk( DUnknown ->
Consistent )
May 8 17:22:50 vm-1 kernel: [ 558.102631] block drbd1: helper command:
/sbin/drbdadm before-resync-source minor-1
May 8 17:22:50 vm-1 kernel: [ 558.107486] block drbd1: helper command:
/sbin/drbdadm before-resync-source minor-1 exit code 0 (0x0)
May 8 17:22:50 vm-1 kernel: [ 558.107503] block drbd1: conn( WFBitMapS
-> SyncSource ) pdsk( Consistent -> Inconsistent )
May 8 17:22:50 vm-1 kernel: [ 558.107519] block drbd1: Began resync as
SyncSource (will sync 12288 KB [3072 bits set]).
May 8 17:22:50 vm-1 kernel: [ 558.107587] block drbd1: updated sync
UUID 1D8582A875D72EB5:0990F992CBAA32F1:098FF992CBAA32F1:248E28A17C6EBF3D
May 8 17:22:50 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 22: monitor p_fence_N1_monitor_60000 on vm-2
May 8 17:22:50 vm-1 kernel: [ 558.639016] block drbd1: Resync done
(total 1 sec; paused 0 sec; 12288 K/sec)
May 8 17:22:50 vm-1 kernel: [ 558.639025] block drbd1: updated UUIDs
1D8582A875D72EB5:0000000000000000:0990F992CBAA32F1:098FF992CBAA32F1
May 8 17:22:50 vm-1 kernel: [ 558.639032] block drbd1: conn(
SyncSource -> Connected ) pdsk( Inconsistent -> UpToDate )
May 8 17:22:50 vm-1 kernel: [ 558.649075] block drbd1: bitmap WRITE of
6 pages took 0 jiffies
May 8 17:22:50 vm-1 kernel: [ 558.650039] block drbd1: 0 KB (0 bits)
marked out-of-sync by on disk bit-map.
May 8 17:22:50 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr) /usr/lib/ocf/resource.d//heartbeat/apache: 440:
kill:
May 8 17:22:50 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr) No such process
May 8 17:22:50 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr)
May 8 17:22:50 vm-1 apache[12624]: INFO: Killing apache PID 11507
May 8 17:22:50 vm-1 apache[12624]: INFO: apache stopped.
May 8 17:22:50 vm-1 lrmd: [3008]: info: operation stop[81] on
p_apache:0 for client 3011: pid 12624 exited with return code 0
May 8 17:22:50 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_stop_0 (call=81, rc=0, cib-update=263,
confirmed=true) ok
May 8 17:22:50 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 80: start p_apache:0_start_0 on vm-1 (local)
May 8 17:22:50 vm-1 lrmd: [3008]: info: rsc:p_apache:0 start[82] (pid
12670)
May 8 17:22:50 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 81: start p_apache:1_start_0 on vm-2
May 8 17:22:51 vm-1 apache[12670]: INFO: apache not running
May 8 17:22:51 vm-1 apache[12670]: INFO: waiting for apache
/etc/apache2/apache2.conf to come up
May 8 17:22:51 vm-1 crmd: [3011]: info: abort_transition_graph:
te_update_diff:176 - Triggered transition abort (complete=0, tag=nvpair,
id=status-vm-2-master-p_drbd_wwwdata.1, name=master-p_drbd_wwwdata:1,
value=1000, magic=NA, cib=0.593.657) : Transient attribute: update
May 8 17:22:52 vm-1 lrmd: [3008]: info: operation start[82] on
p_apache:0 for client 3011: pid 12670 exited with return code 0
May 8 17:22:52 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_start_0 (call=82, rc=0, cib-update=264,
confirmed=true) ok
May 8 17:22:52 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 17
(Complete=42, Pending=0, Fired=0, Skipped=3, Incomplete=1,
Source=/var/lib/pengine/pe-input-2181.bz2): Stopped
May 8 17:22:52 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC
cause=C_FSA_INTERNAL origin=notify_crmd ]
May 8 17:22:52 vm-1 pengine: [3010]: notice: unpack_config: On loss of
CCM Quorum: Ignore
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Promote
p_drbd_wwwdata:1#011(Slave -> Master vm-2)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Start
p_controld_dlm:0#011(vm-2)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Start
p_o2cb:0#011(vm-2)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Start
WebFS:0#011(vm-2)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Restart
p_apache:0#011(Started vm-1)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Restart
p_apache:1#011(Started vm-2)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Start
p_IP:0#011(vm-1)
May 8 17:22:52 vm-1 pengine: [3010]: notice: LogActions: Start
p_IP:1#011(vm-2)
May 8 17:22:52 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS
cause=C_IPC_MESSAGE origin=handle_response ]
May 8 17:22:52 vm-1 crmd: [3011]: info: do_te_invoke: Processing graph
18 (ref=pe_calc-dc-1431098572-273) derived from
/var/lib/pengine/pe-input-2182.bz2
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 6: cancel p_drbd_wwwdata:1_monitor_60000 on vm-2
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 100: notify p_drbd_wwwdata:0_pre_notify_promote_0 on vm-1 (local)
May 8 17:22:52 vm-1 lrmd: [3008]: info: rsc:p_drbd_wwwdata:0 notify[83]
(pid 12776)
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 102: notify p_drbd_wwwdata:1_pre_notify_promote_0 on vm-2
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 71: stop p_apache:0_stop_0 on vm-1 (local)
May 8 17:22:52 vm-1 lrmd: [3008]: info: rsc:p_apache:0 stop[84] (pid 12777)
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 74: stop p_apache:1_stop_0 on vm-2
May 8 17:22:52 vm-1 pengine: [3010]: notice: process_pe_message:
Transition 18: PEngine Input stored in: /var/lib/pengine/pe-input-2182.bz2
May 8 17:22:52 vm-1 lrmd: [3008]: info: operation notify[83] on
p_drbd_wwwdata:0 for client 3011: pid 12776 exited with return code 0
May 8 17:22:52 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_drbd_wwwdata:0_notify_0 (call=83, rc=0, cib-update=0,
confirmed=true) ok
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 22: promote p_drbd_wwwdata:1_promote_0 on vm-2
May 8 17:22:52 vm-1 kernel: [ 560.076628] block drbd1: peer( Secondary
-> Primary )
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 101: notify p_drbd_wwwdata:0_post_notify_promote_0 on vm-1 (local)
May 8 17:22:52 vm-1 lrmd: [3008]: info: rsc:p_drbd_wwwdata:0 notify[85]
(pid 12831)
May 8 17:22:52 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 103: notify p_drbd_wwwdata:1_post_notify_promote_0 on vm-2
May 8 17:22:52 vm-1 lrmd: [3008]: info: RA output:
(p_drbd_wwwdata:0:notify:stdout)
May 8 17:22:52 vm-1 lrmd: [3008]: info: operation notify[85] on
p_drbd_wwwdata:0 for client 3011: pid 12831 exited with return code 0
May 8 17:22:52 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_drbd_wwwdata:0_notify_0 (call=85, rc=0, cib-update=0,
confirmed=true) ok
May 8 17:22:52 vm-1 crmd: [3011]: info: abort_transition_graph:
te_update_diff:176 - Triggered transition abort (complete=0, tag=nvpair,
id=status-vm-2-master-p_drbd_wwwdata.1, name=master-p_drbd_wwwdata:1,
value=10000, magic=NA, cib=0.593.665) : Transient attribute: update
May 8 17:22:53 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr) /usr/lib/ocf/resource.d//heartbeat/apache: 440:
kill:
May 8 17:22:53 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr) No such process
May 8 17:22:53 vm-1 lrmd: [3008]: info: RA output:
(p_apache:0:stop:stderr)
May 8 17:22:53 vm-1 apache[12777]: INFO: Killing apache PID 12701
May 8 17:22:53 vm-1 apache[12777]: INFO: apache stopped.
May 8 17:22:53 vm-1 lrmd: [3008]: info: operation stop[84] on
p_apache:0 for client 3011: pid 12777 exited with return code 0
May 8 17:22:53 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_stop_0 (call=84, rc=0, cib-update=266,
confirmed=true) ok
May 8 17:22:53 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 18
(Complete=16, Pending=0, Fired=0, Skipped=20, Incomplete=5,
Source=/var/lib/pengine/pe-input-2182.bz2): Stopped
May 8 17:22:53 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_POLICY_ENGINE [ input=I_PE_CALC
cause=C_FSA_INTERNAL origin=notify_crmd ]
May 8 17:22:53 vm-1 pengine: [3010]: notice: unpack_config: On loss of
CCM Quorum: Ignore
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_controld_dlm:0#011(vm-2)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_o2cb:0#011(vm-2)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
WebFS:0#011(vm-2)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_apache:0#011(vm-1)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_apache:1#011(vm-2)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_IP:0#011(vm-1)
May 8 17:22:53 vm-1 pengine: [3010]: notice: LogActions: Start
p_IP:1#011(vm-2)
May 8 17:22:53 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_POLICY_ENGINE -> S_TRANSITION_ENGINE [ input=I_PE_SUCCESS
cause=C_IPC_MESSAGE origin=handle_response ]
May 8 17:22:53 vm-1 crmd: [3011]: info: do_te_invoke: Processing graph
19 (ref=pe_calc-dc-1431098573-284) derived from
/var/lib/pengine/pe-input-2183.bz2
May 8 17:22:53 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 6: cancel p_drbd_wwwdata:1_monitor_60000 on vm-2
May 8 17:22:53 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 47: start p_controld_dlm:0_start_0 on vm-2
May 8 17:22:53 vm-1 cib: [3006]: info: cib_process_request: Operation
complete: op cib_delete for section
//node_state[@uname='vm-2']//lrm_resource[@id='p_drbd_wwwdata:1']/lrm_rsc_op[@id='p_drbd_wwwdata:1_monitor_60000']
(origin=vm-2/crmd/24, version=0.593.668): ok (rc=0)
May 8 17:22:53 vm-1 pengine: [3010]: notice: process_pe_message:
Transition 19: PEngine Input stored in: /var/lib/pengine/pe-input-2183.bz2
May 8 17:22:53 vm-1 stonith-ng: [3007]: info: stonith_command:
Processed st_execute from lrmd: rc=-1
May 8 17:22:53 vm-1 external/libvirt[12878]: [12893]: notice:
qemu+tcp://192.168.122.1/system: Running hypervisor: QEMU 2.0.0
May 8 17:22:54 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 48: monitor p_controld_dlm:0_monitor_120000 on vm-2
May 8 17:22:54 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 55: start p_o2cb:0_start_0 on vm-2
May 8 17:22:54 vm-1 stonith: [12871]: info: external/libvirt device OK.
May 8 17:22:54 vm-1 stonith-ng: [3007]: info: log_operation:
p_fence_N2: Performing: stonith -t external/libvirt -S
May 8 17:22:54 vm-1 stonith-ng: [3007]: info: log_operation:
p_fence_N2: success: 0
May 8 17:22:56 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 56: monitor p_o2cb:0_monitor_10000 on vm-2
May 8 17:22:56 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 63: start WebFS:0_start_0 on vm-2
May 8 17:22:56 vm-1 kernel: [ 564.278505] dlm: got connection from
930785472
May 8 17:22:56 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 64: monitor WebFS:0_monitor_10000 on vm-2
May 8 17:22:56 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 71: start p_apache:0_start_0 on vm-1 (local)
May 8 17:22:56 vm-1 lrmd: [3008]: info: rsc:p_apache:0 start[86] (pid
12894)
May 8 17:22:56 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 73: start p_apache:1_start_0 on vm-2
May 8 17:22:56 vm-1 apache[12894]: INFO: apache not running
May 8 17:22:56 vm-1 apache[12894]: INFO: waiting for apache
/etc/apache2/apache2.conf to come up
May 8 17:22:57 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 74: monitor p_apache:1_monitor_60000 on vm-2
May 8 17:22:57 vm-1 lrmd: [3008]: info: operation start[86] on
p_apache:0 for client 3011: pid 12894 exited with return code 0
May 8 17:22:57 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_start_0 (call=86, rc=0, cib-update=268,
confirmed=true) ok
May 8 17:22:57 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 72: monitor p_apache:0_monitor_60000 on vm-1 (local)
May 8 17:22:57 vm-1 lrmd: [3008]: info: rsc:p_apache:0 monitor[87] (pid
13000)
May 8 17:22:57 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 79: start p_IP:0_start_0 on vm-1 (local)
May 8 17:22:57 vm-1 lrmd: [3008]: info: rsc:p_IP:0 start[88] (pid 13001)
May 8 17:22:57 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 81: start p_IP:1_start_0 on vm-2
May 8 17:22:57 vm-1 lrmd: [3008]: info: operation monitor[87] on
p_apache:0 for client 3011: pid 13000 exited with return code 0
May 8 17:22:57 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_apache:0_monitor_60000 (call=87, rc=0, cib-update=269,
confirmed=false) ok
May 8 17:22:57 vm-1 IPaddr2[13001]: INFO: ip -f inet addr add
192.168.122.200/32 brd 192.168.122.200 dev eth0
May 8 17:22:57 vm-1 IPaddr2[13001]: INFO: ip link set eth0 up
May 8 17:22:57 vm-1 IPaddr2[13001]: INFO: /usr/lib/heartbeat/send_arp
-i 200 -r 5 -p /var/run/resource-agents/send_arp-192.168.122.200 eth0
192.168.122.200 8bbd5f0b558f not_used not_used
May 8 17:22:57 vm-1 lrmd: [3008]: info: operation start[88] on p_IP:0
for client 3011: pid 13001 exited with return code 0
May 8 17:22:57 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_start_0 (call=88, rc=0, cib-update=270, confirmed=true) ok
May 8 17:22:57 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 80: monitor p_IP:0_monitor_10000 on vm-1 (local)
May 8 17:22:57 vm-1 lrmd: [3008]: info: rsc:p_IP:0 monitor[89] (pid 13103)
May 8 17:22:57 vm-1 lrmd: [3008]: info: operation monitor[89] on p_IP:0
for client 3011: pid 13103 exited with return code 0
May 8 17:22:57 vm-1 crmd: [3011]: info: process_lrm_event: LRM
operation p_IP:0_monitor_10000 (call=89, rc=0, cib-update=271,
confirmed=false) ok
May 8 17:22:58 vm-1 crmd: [3011]: info: te_rsc_command: Initiating
action 82: monitor p_IP:1_monitor_10000 on vm-2
May 8 17:22:58 vm-1 crmd: [3011]: notice: run_graph: ==== Transition 19
(Complete=25, Pending=0, Fired=0, Skipped=0, Incomplete=0,
Source=/var/lib/pengine/pe-input-2183.bz2): Complete
May 8 17:22:58 vm-1 crmd: [3011]: notice: do_state_transition: State
transition S_TRANSITION_ENGINE -> S_IDLE [ input=I_TE_SUCCESS
cause=C_FSA_INTERNAL origin=notify_crmd ]
More information about the Users
mailing list