[ClusterLabs] VM failure during shutdown
Ken Gaillot
kgaillot at redhat.com
Mon Jun 25 12:15:16 EDT 2018
On Mon, 2018-06-25 at 09:47 -0500, Ken Gaillot wrote:
> On Mon, 2018-06-25 at 11:33 +0300, Vaggelis Papastavros wrote:
> > Dear friends ,
> >
> > We have the following configuration :
> >
> > CentOS7 , pacemaker 0.9.152 and Corosync 2.4.0, storage with DRBD
> > and
> > stonith eanbled with APC PDU devices.
> >
> > I have a windows VM configured as cluster resource with the
> > following
> > attributes :
> >
> > Resource: WindowSentinelOne_res (class=ocf provider=heartbeat
> > type=VirtualDomain)
> > Attributes: hypervisor=qemu:///system
> > config=/opt/customer_vms/conf/WindowSentinelOne/WindowSentinelOne.x
> > ml
> >
> > migration_transport=ssh
> > Utilization: cpu=8 hv_memory=8192
> > Operations: start interval=0s timeout=120s
> > (WindowSentinelOne_res-start-interval-0s)
> > stop interval=0s timeout=120s
> > (WindowSentinelOne_res-stop-interval-0s)
> > monitor interval=10s timeout=30s
> > (WindowSentinelOne_res-monitor-interval-10s)
> >
> > under some circumstances (which i try to identify) the VM fails
> > and
> > disappears under virsh list --all and also pacemaker reports the VM
> > as
> > stopped .
> >
> > If run pcs resource cleanup windows_wm everything is OK, but i
> > can't
> > identify the reason of failure.
> >
> > For example when shutdown the VM (with windows shutdown) the
> > cluster
> > reports the following :
> >
> > WindowSentinelOne_res (ocf::heartbeat:VirtualDomain): Started
> > sgw-
> > 02
> > (failure ignored)
> >
> > Failed Actions:
> > * WindowSentinelOne_res_monitor_10000 on sgw-02 'not running' (7):
> > call=67, status=complete, exitreason='none',
> > last-rc-change='Mon Jun 25 07:41:37 2018', queued=0ms,
> > exec=0ms.
> >
> >
> > My questions are
> >
> > 1) why the VM shutdown is reported as (FailedAction) from cluster ?
> > Its
> > a worthy operation during VM life cycle .
>
> Pacemaker has no way of knowing that the VM was intentionally shut
> down, vs crashed.
>
> When some resource is managed by the cluster, all starts and stops of
> the resource have to go through the cluster. You can either set
> target-
> role=Stopped in the resource configuration, or if it's a temporary
> issue (e.g. rebooting for some OS updates), you could set is-
> managed=false to take it out of cluster control, do the work, then
> set
> is-managed=true again.
Also, a nice feature is that you can use rules to set a maintenance
window ahead of time (especially helpful if the person who maintains
the cluster isn't the same person who needs to do the VM updates). For
example, you could set a rule that the resource's is-managed option
will be false from 9pm to midnight on Fridays. See:
http://clusterlabs.org/pacemaker/doc/en-US/Pacemaker/1.1/html-single/Pa
cemaker_Explained/index.html#idm140583511697312
particularly the parts about time/date expressions and using rules to
control resource options.
>
> > 2) why sometimes the resource is marked as stopped (the VM is
> > healthy)
> > and needs cleanup ?
>
> That's a problem. If the VM is truly healthy, it sounds like there's
> an
> issue with the resource agent. You'd have to look at the logs to see
> if
> it gave any more information (e.g. if it's a timeout, raising the
> timeout might be sufficient).
>
> > 3) I can't understand the corosync logs ... during the the VM
> > shutdown
> > corosync logs is the following
>
> FYI, the system log will have the most important messages.
> corosync.log
> will additionally have info-level messages -- potentially helpful but
> definitely difficult to follow.
>
> > Jun 25 07:41:37 [5140] sgw-02 crmd: info:
> > process_lrm_event: Result of monitor operation for
> > WindowSentinelOne_res on sgw-02: 7 (not running) | call=67
> > key=WindowSentinelOne_res_monitor_10000 confirmed=false cib-
> > update=36
>
> This is really the only important message. It says that a recurring
> monitor on the WindowSentinelOne_res resource on node sgw-02 exited
> with status code 7 (which means the resource agent thinks the
> resource
> is not running).
>
> 'key=WindowSentinelOne_res_monitor_10000' is how pacemaker identifies
> resource agent actions. The format is <resource-name>_<action-
> name>_<action-interval-in-milliseconds>
>
> This is the only information Pacemaker will get from the resource
> agent. To investigate more deeply, you'll have to check for log
> messages from the agent itself.
>
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Forwarding cib_modify operation for
> > section
> > status to all (origin=local/crmd/36)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: --- 0.4704.67 2
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: +++ 0.4704.68 (null)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > + /cib: @num_updates=68
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > + /cib/status/node_state[@id='2']: @crm-debug-
> > origin=do_update_resource
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > ++
> > /cib/status/node_state[@id='2']/lrm[@id='2']/lrm_resources/lrm_reso
> > ur
> > ce[@id='WindowSentinelOne_res']:
> > <lrm_rsc_op id="WindowSentinelOne_res_last_failure_0"
> > operation_key="WindowSentinelOne_res_monitor_10000"
> > operation="monitor"
> > crm-debug-origin="do_update_resource" crm_feature_set="3.0.10"
> > transition-key="84:3:0:f910c793-a714-4e24-80d1-b0ec66275491"
> > transition-magic="0:7;84:3:0:f910c793-a714-4e24-80d1-b0ec66275491"
> > on_node="sgw-02" cal
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Completed cib_modify operation for section
> > status: OK (rc=0, origin=sgw-02/crmd/36, version=0.4704.68)
>
> You can usually ignore the 'cib' messages. This just means Pacemaker
> recorded the result on disk.
>
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_peer_update: Setting fail-count-WindowSentinelOne_res[sgw-
> > 02]:
> > (null) -> 1 from sgw-01
>
> Since the cluster expected the resource to be running, this result is
> a
> failure. Failures are counted using special node attributes that
> start
> with "fail-count-". This is what Pacemaker uses to determine if a
> resource has reached its migration-threshold.
>
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > write_attribute:
> > Sent update 10 with 1 changes for fail-count-
> > WindowSentinelOne_res,
> > id=<n/a>, set=(null)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Forwarding cib_modify operation for
> > section
> > status to all (origin=local/attrd/10)
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_peer_update: Setting
> > last-failure-WindowSentinelOne_res[sgw-02]: (null) -> 1529912497
> > from
> > sgw-01
>
> Similarly, the time the failure occurred is stored in a 'last-
> failure-'
> node attribute, which Pacemaker uses to determine if a resource has
> reached its failure-timeout.
>
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > write_attribute:
> > Sent update 11 with 1 changes for last-failure-
> > WindowSentinelOne_res,
> > id=<n/a>, set=(null)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Forwarding cib_modify operation for
> > section
> > status to all (origin=local/attrd/11)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: --- 0.4704.68 2
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: +++ 0.4704.69 (null)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > + /cib: @num_updates=69
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > ++
> > /cib/status/node_state[@id='2']/transient_attributes[@id='2']/insta
> > nc
> > e_attributes[@id='status-2']:
> > <nvpair id="status-2-fail-count-WindowSentinelOne_res"
> > name="fail-count-WindowSentinelOne_res" value="1"/>
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Completed cib_modify operation for section
> > status: OK (rc=0, origin=sgw-02/attrd/10, version=0.4704.69)
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_cib_callback: Update 10 for fail-count-
> > WindowSentinelOne_res:
> > OK (0)
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_cib_callback: Update 10 for
> > fail-count-WindowSentinelOne_res[sgw-02]=1: OK (0)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: --- 0.4704.69 2
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > Diff: +++ 0.4704.70 (null)
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > + /cib: @num_updates=70
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_perform_op:
> > ++
> > /cib/status/node_state[@id='2']/transient_attributes[@id='2']/insta
> > nc
> > e_attributes[@id='status-2']:
> > <nvpair id="status-2-last-failure-WindowSentinelOne_res"
> > name="last-failure-WindowSentinelOne_res" value="1529912497"/>
> > Jun 25 07:41:37 [5130] sgw-02 cib: info:
> > cib_process_request: Completed cib_modify operation for section
> > status: OK (rc=0, origin=sgw-02/attrd/11, version=0.4704.70)
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_cib_callback: Update 11 for last-failure-
> > WindowSentinelOne_res:
> > OK (0)
> > Jun 25 07:41:37 [5137] sgw-02 attrd: info:
> > attrd_cib_callback: Update 11 for
> > last-failure-WindowSentinelOne_res[sgw-02]=1529912497: OK (0)
> > Jun 25 07:41:42 [5130] sgw-02 cib: info:
> > cib_process_ping:
> > Reporting our current digest to sgw-01:
> > 3e27415fcb003ef3373b47ffa6c5f358
> > for 0.4704.70 (0x7faac1729720 0)
> >
> > Sincerely ,
> >
> > Vaggelis Papastavros
--
Ken Gaillot <kgaillot at redhat.com>
More information about the Users
mailing list