[ClusterLabs] Q: wrong "unexpected shutdown of DC" detected

[Ulrich Windl]

Hi!

I wanted to reboot one node (h18) of our 3-node cluster, so I did this remotely from h16:
h16:~ # ssh rksaph18 crm cluster stop
INFO: Cluster services stopped

Unfortunately I wasn't aware that the other node (h19) wasn't running cluster services, too, so the quorum will be lost.
Firs it looks OK, but then h16 had been fenced. h18 had been DC before.
Here are the logs around the time when h18 stopped cluster services:

Jan 27 10:42:01 h16 pacemaker-execd[25960]:  notice: executing - rsc:prm_stonith_sbd action:start call_id:96
Jan 27 10:42:03 h16 pacemaker-execd[25960]:  notice: prm_stonith_sbd start (call 96) exited with status 0 (execution time 1985ms, queue time 15001ms)
Jan 27 10:42:03 h16 pacemaker-controld[25963]:  notice: Result of start operation for prm_stonith_sbd on h16: ok
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: Result of monitor operation for prm_stonith_sbd on h16: ok
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: Our peer on the DC (h18) is dead
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: State transition S_NOT_DC -> S_ELECTION
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: State transition S_ELECTION -> S_INTEGRATION
Jan 27 10:42:05 h16 pacemaker-attrd[25961]:  notice: Lost attribute writer h18
Jan 27 10:42:05 h16 pacemaker-attrd[25961]:  notice: Node h18 state is now lost
Jan 27 10:42:05 h16 pacemaker-attrd[25961]:  notice: Removing all h18 attributes for peer loss
Jan 27 10:42:05 h16 pacemaker-attrd[25961]:  notice: Purged 1 peer with id=118 and/or uname=h18 from the membership cache
Jan 27 10:42:05 h16 pacemaker-attrd[25961]:  notice: Recorded local node as attribute writer (was unset)
Jan 27 10:42:05 h16 pacemaker-fenced[25959]:  notice: Node h18 state is now lost
Jan 27 10:42:05 h16 pacemaker-fenced[25959]:  notice: Purged 1 peer with id=118 and/or uname=h18 from the membership cache
Jan 27 10:42:05 h16 pacemaker-based[25958]:  notice: Node h18 state is now lost
Jan 27 10:42:05 h16 pacemaker-based[25958]:  notice: Purged 1 peer with id=118 and/or uname=h18 from the membership cache
Jan 27 10:42:05 h16 corosync[25949]:   [TOTEM ] A new membership (172.20.16.16:42344) was formed. Members left: 118
Jan 27 10:42:05 h16 corosync[25949]:   [CPG   ] downlist left_list: 1 received
Jan 27 10:42:05 h16 corosync[25949]:   [QUORUM] This node is within the non-primary component and will NOT provide any services.
Jan 27 10:42:05 h16 corosync[25949]:   [QUORUM] Members[1]: 116
Jan 27 10:42:05 h16 kernel: dlm: closing connection to node 118
Jan 27 10:42:05 h16 corosync[25949]:   [MAIN  ] Completed service synchronization, ready to provide service.
Jan 27 10:42:05 h16 pacemakerd[25957]:  warning: Quorum lost
Jan 27 10:42:05 h16 pacemakerd[25957]:  notice: Node h18 state is now lost
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  warning: Quorum lost
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: Node h18 state is now lost
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  warning: Stonith/shutdown of node h18 was not expected
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: Updating quorum status to false (call=129)
Jan 27 10:42:05 h16 pacemaker-controld[25963]:  notice: Updating quorum status to false (call=142)
Jan 27 10:42:05 h16 corosync[25949]:   [TOTEM ] Automatically recovered ring 1
Jan 27 10:42:06 h16 sbd[25937]:  warning: inquisitor_child: pcmk health check: UNHEALTHY
Jan 27 10:42:06 h16 sbd[25937]:  warning: inquisitor_child: Servant pcmk is outdated (age: 523664)
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice: Watchdog will be used via SBD if fencing is required and stonith-watchdog-timeout is nonzero
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  warning: Fencing and resource management disabled due to lack of quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_stonith_sbd	 ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_DLM:0		   ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_virtlockd:0	 ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_lockspace_raid_md10:0	 ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_lockspace_ocfs2:0		 ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_CFS_VMI:0				 ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_cron_snap_v02	    ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_cron_snap_test-jeos1	  ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_cron_snap_test-jeos2	  ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_cron_snap_test-jeos3	  ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_cron_snap_test-jeos4	  ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_xen_test-jeos1		    ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_xen_test-jeos2		    ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_xen_test-jeos3		    ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice:  * Stop  	 prm_xen_test-jeos4		    ( h16 )   due to no quorum
Jan 27 10:42:06 h16 pacemaker-schedulerd[25962]:  notice: Calculated transition 0, saving inputs in /var/lib/pacemaker/pengine/pe-input-43.bz2
Jan 27 10:42:06 h16 pacemaker-controld[25963]:  notice: Processing graph 0 (ref=pe_calc-dc-1611740526-14) derived from /var/lib/pacemaker/pengine/pe-input-43.bz2
Jan 27 10:42:06 h16 pacemaker-controld[25963]:  notice: Initiating stop operation prm_stonith_sbd_stop_0 locally on h16
Jan 27 10:42:16 h16 dlm_controld[26304]: 523675 fence work wait for quorum
Jan 27 10:42:18 h16 Filesystem(prm_CFS_VMI)[11564]: INFO: Running stop for /dev/disk/by-id/dm-name-VMI-PM on /cfs/VMI
Jan 27 10:42:18 h16 Filesystem(prm_CFS_VMI)[11594]: INFO: Trying to unmount /cfs/VMI
Jan 27 10:42:18 h16 systemd[1]: Stopping Virtualization daemon...
Jan 27 10:42:18 h16 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: leaving the lockspace group...
Jan 27 10:42:18 h16 systemd[1]: Stopped Virtualization daemon.
Jan 27 10:42:18 h16 systemd[1]: Stopping Virtual machine lock manager...
Jan 27 10:42:18 h16 systemd[1]: Stopped Virtual machine lock manager.
Jan 27 10:42:18 h16 systemd[1]: Closed Virtual machine lock manager admin socket.
Jan 27 10:42:18 h16 systemd[1]: Closed Virtual machine lock manager socket.
Jan 27 10:42:20 h16 pacemaker-controld[25963]:  notice: Result of stop operation for prm_virtlockd on h16: ok
Jan 27 10:42:20 h16 pacemaker-controld[25963]:  notice: Initiating stop operation prm_lockspace_ocfs2_stop_0 locally on h16
Jan 27 10:42:20 h16 pacemaker-execd[25960]:  notice: executing - rsc:prm_lockspace_ocfs2 action:stop call_id:131
Jan 27 10:42:20 h16 Filesystem(prm_lockspace_ocfs2)[11643]: INFO: Running stop for /dev/md10 on /var/lib/libvirt/lockd
Jan 27 10:42:21 h16 Filesystem(prm_lockspace_ocfs2)[11668]: INFO: Trying to unmount /var/lib/libvirt/lockd
Jan 27 10:43:13 h16 dlm_controld[26304]: 523732 790F9C237C2A45758135FE4945B7A744 wait for quorum
Jan 27 10:43:48 h16 pacemaker-execd[25960]:  warning: prm_CFS_VMI_stop_0 process (PID 11502) timed out
Jan 27 10:43:48 h16 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: group event done -512 0
Jan 27 10:43:48 h16 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: group leave failed -512 0
Jan 27 10:43:48 h16 kernel: dlm: 790F9C237C2A45758135FE4945B7A744: release_lockspace final free
Jan 27 10:43:48 h16 kernel: dlm: A53F83720CCF4CCA877BE1E60F6F507D: leaving the lockspace group...
Jan 27 10:43:48 h16 pacemaker-execd[25960]:  warning: prm_CFS_VMI_stop_0[11502] timed out after 90000ms
Jan 27 10:43:48 h16 pacemaker-execd[25960]:  notice: prm_CFS_VMI stop (call 129, PID 11502) exited with status 1 (execution time 90007ms, queue time 0ms)
Jan 27 10:43:48 h16 pacemaker-controld[25963]:  error: Result of stop operation for prm_CFS_VMI on h16: Timed Out
Jan 27 10:43:48 h16 ocfs2_hb_ctl[11728]: ocfs2_hb_ctl /sbin/ocfs2_hb_ctl -K -u 790F9C237C2A45758135FE4945B7A744
Jan 27 10:43:48 h16 pacemaker-controld[25963]:  notice: Transition 0 aborted by operation prm_CFS_VMI_stop_0 'modify' on h16: Event failed
Jan 27 10:43:48 h16 pacemaker-controld[25963]:  notice: Transition 0 action 45 (prm_CFS_VMI_stop_0 on h16): expected 'ok' but got 'error'
Jan 27 10:43:48 h16 pacemaker-attrd[25961]:  notice: Setting fail-count-prm_CFS_VMI#stop_0[h16]: (unset) -> INFINITY
Jan 27 10:43:48 h16 pacemaker-attrd[25961]:  notice: Setting last-failure-prm_CFS_VMI#stop_0[h16]: (unset) -> 1611740628
Jan 27 10:43:48 h16 kernel: ocfs2: Unmounting device (254,13) on (node 116)
Jan 27 10:43:48 h16 pacemaker-controld[25963]:  notice: Transition 0 aborted by transient_attributes.116 'create': Transient attribute change
Jan 27 10:43:50 h16 pacemaker-execd[25960]:  warning: prm_lockspace_ocfs2_stop_0 process (PID 11605) timed out
Jan 27 10:43:50 h16 pacemaker-execd[25960]:  warning: prm_lockspace_ocfs2_stop_0[11605] timed out after 90000ms
Jan 27 10:43:50 h16 pacemaker-execd[25960]:  notice: prm_lockspace_ocfs2 stop (call 131, PID 11605) exited with status 1 (execution time 90005ms, queue time 0ms)
Jan 27 10:43:50 h16 kernel: dlm: A53F83720CCF4CCA877BE1E60F6F507D: group event done -512 0
Jan 27 10:43:50 h16 kernel: dlm: A53F83720CCF4CCA877BE1E60F6F507D: group leave failed -512 0
Jan 27 10:43:50 h16 kernel: dlm: A53F83720CCF4CCA877BE1E60F6F507D: release_lockspace final free
Jan 27 10:43:50 h16 pacemaker-controld[25963]:  error: Result of stop operation for prm_lockspace_ocfs2 on h16: Timed Out
Jan 27 10:43:50 h16 ocfs2_hb_ctl[11731]: ocfs2_hb_ctl /sbin/ocfs2_hb_ctl -K -u A53F83720CCF4CCA877BE1E60F6F507D
Jan 27 10:43:50 h16 pacemaker-controld[25963]:  notice: Transition 0 action 39 (prm_lockspace_ocfs2_stop_0 on h16): expected 'ok' but got 'error'
Jan 27 10:43:50 h16 pacemaker-controld[25963]:  notice: Transition 0 (Complete=23, Pending=0, Fired=0, Skipped=0, Incomplete=5, Source=/var/lib/pacemaker/pengine/pe-input-43.bz2): Complete
Jan 27 10:43:50 h16 pacemaker-attrd[25961]:  notice: Setting fail-count-prm_lockspace_ocfs2#stop_0[h16]: (unset) -> INFINITY
Jan 27 10:43:50 h16 pacemaker-attrd[25961]:  notice: Setting last-failure-prm_lockspace_ocfs2#stop_0[h16]: (unset) -> 1611740630
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Watchdog will be used via SBD if fencing is required and stonith-watchdog-timeout is nonzero
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Fencing and resource management disabled due to lack of quorum
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Unexpected result (error) was recorded for stop of prm_CFS_VMI:0 on h16 at Jan 27 10:42:18 2021
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Unexpected result (error) was recorded for stop of prm_CFS_VMI:0 on h16 at Jan 27 10:42:18 2021
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: We can fence h16 without quorum because they're in our membership
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Cluster node h16 will be fenced: prm_CFS_VMI:0 failed there
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Unexpected result (error) was recorded for stop of prm_lockspace_ocfs2:0 on h16 at Jan 27 10:42:20 2021
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Unexpected result (error) was recorded for stop of prm_lockspace_ocfs2:0 on h16 at Jan 27 10:42:20 2021
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Forcing cln_CFS_VMI away from h16 after 1000000 failures (max=1000000)
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Forcing cln_CFS_VMI away from h16 after 1000000 failures (max=1000000)
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Forcing cln_CFS_VMI away from h16 after 1000000 failures (max=1000000)
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_raid_md10:0 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_raid_md10:1 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_raid_md10:2 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:1 with instance of cln_lockspace_raid_md10
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:1 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:2 with instance of cln_lockspace_raid_md10
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:2 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:0 with instance of cln_lockspace_raid_md10
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_lockspace_ocfs2:0 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_virtlockd:0 with instance of cln_lockspace_ocfs2
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_virtlockd:1 with instance of cln_lockspace_ocfs2
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_virtlockd:2 with instance of cln_lockspace_ocfs2
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_CFS_VMI:1 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_CFS_VMI:2 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: Cannot pair prm_CFS_VMI:0 with instance of cln_DLM
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: We can fence h16 without quorum because they're in our membership
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  notice: We can fence h16 without quorum because they're in our membership
Jan 27 10:43:50 h16 pacemaker-schedulerd[25962]:  warning: Scheduling Node h16 for STONITH

Up to the "Members left: 118" everything looks normal. However "warning: Stonith/shutdown of node h18 was not expected" does not. 
However while not having quorum, the node tries to stop resources. And that mostly works, until OCFS is going to be unmounted. That seems to wait for a quorum, eventually timing out.

Most importantly an earlier log message confirmed that h18 is going to be stopped:
Jan 27 10:41:46 h16 pacemaker-attrd[25961]:  notice: Setting shutdown[h18]: (unset) -> 1611740506

Messages on h18:
Jan 27 10:41:46 h18 systemd[1]: Stopping Pacemaker High Availability Cluster Manager...
Jan 27 10:41:46 h18 pacemakerd[42331]:  notice: Caught 'Terminated' signal
Jan 27 10:41:46 h18 pacemakerd[42331]:  notice: Shutting down Pacemaker
...
Jan 27 10:41:46 h18 pacemaker-attrd[42335]:  notice: Setting shutdown[h18]: (unset) -> 1611740506
...
Jan 27 10:41:46 h18 pacemaker-schedulerd[42336]:  notice: Scheduling shutdown of node h18
...
Jan 27 10:42:05 h18 pacemakerd[42331]:  notice: Shutdown complete
...
Jan 27 10:42:05 h18 corosync[26598]: Waiting for corosync services to unload:[  OK  ]
Jan 27 10:42:05 h18 systemd[1]: Stopped Corosync Cluster Engine.
Jan 27 10:42:05 h18 sbd[42312]:  warning: cleanup_servant_by_pid: Servant for /dev/disk/by-id/dm-name-SBD_1-3P1 (pid: 42317) has terminated
Jan 27 10:42:05 h18 sbd[42312]:  warning: cleanup_servant_by_pid: Servant for /dev/disk/by-id/dm-name-SBD_1-3P2 (pid: 42318) has terminated
Jan 27 10:42:05 h18 systemd[1]: Stopped Shared-storage based fencing daemon.
Jan 27 10:42:05 h18 sshd[25751]: Received disconnect from 172.20.16.16 port 46118:11: disconnected by user
Jan 27 10:42:05 h18 sshd[25751]: Disconnected from user root 172.20.16.16 port 46118

Software is up-to-date SLES15 SP2:
pacemaker-2.0.4+20200616.2deceaa3a-3.3.1.x86_64
corosync-2.4.5-6.3.2.x86_64

The no-quorum policy is default (I couldn't find a setting). Obviously the policy is to stop resources on loss of quorum.
Wouldn't it be better to keep things ("freeze"), hoping for the best? If the other nodes can form a quorum, theid either join the cluster or fence the remaining node then...

I wonder what will happen from this state if one of the other nodes gets online again:

Node List:
  * Node h18: UNCLEAN (offline)
  * Node h19: UNCLEAN (offline)
  * Online: [ h16 ]

Without quorum h16 does not fence the other nodes, so they will remain unclean. If the node becomes online again, h16 will probably see an unclean node, but then has a quorum, and it will first fence it, right? If so, is there a way to avoid that?

Actually that is what happened:
Jan 27 11:34:41 h16 pacemaker-schedulerd[7466]:  warning: Scheduling Node h18 for STONITH
Jan 27 11:34:41 h16 pacemaker-schedulerd[7466]:  notice:  * Fence (reboot) h18 'node is unclean'

Finally: ;-)

Jan 27 11:35:14 h19 pacemaker-fenced[2099]:  notice: Versions did not change in patch 0.250.39
Jan 27 11:36:43 h19 pacemaker-fenced[2099]:  notice: Operation 'reboot' targeting h18 on h16 for pacemaker-controld.7467 at h16.46c6f6cc: OK
Jan 27 11:36:43 h19 pacemaker-fenced[2099]:  error: stonith_construct_reply: Triggered assert at fenced_commands.c:2363 : request != NULL
Jan 27 11:36:43 h19 pacemaker-fenced[2099]:  warning: Can't create a sane reply

Regards,
Ulrich





-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.clusterlabs.org/pipermail/users/attachments/20210127/9f200622/attachment-0001.htm>