Cluster Service shutdown taking 60+ minutes?

All replies

• 

  

  0

  Sign in to vote

  OK, looks like SCVMM could be in the pciture.  Typically in a controlled scenario where a Hyper-V cluster is involved and SCVMM is managing it, the 'best practice' is to have SCVMM place the node in Maintenance mode (http://blogs.technet.com/b/chengw/archive/2009/03/18/what-you-need-to-know-about-maintenance-mode.aspx)which will result in all workloads being removed from the node in question and moved to other nodes.  This then allows a cluster node to be rebooted if needed.

  Has that process been used?  Or, did one just decide out of the blue to reboot a cluster node that had virtualized workloads running on it?

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  Tuesday, August 16, 2011 5:05 PM
• 

  

  0

  Sign in to vote

  Yes I am using SCVMMM 2008 R2.  This node was placed into maintenance mode and all resources were moved.  Both Hyper-V resources and CSV ownership was migrated prior to attempting to reboot.  This was not just a hit reboot and hope everything flees the node.  Also to attept to make sure nothing else was happening I paused the node in Cluster Manager.  I have tried it without node paused as well and it didn't help.
  

  Tuesday, August 16, 2011 5:16 PM
• 

  

  0

  Sign in to vote

  Here is another log for same server when I shut down the service manually prior to reboot so I could watch it better.  I will be shutting down other nodes shortly and will add those logs.  The interesting thing is the timing is almost exactly the same, about 68 minutes.  Not sure where that timeout is coming from.

  00000528.000005c0::2011/08/16-16:33:51.467 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-16:38:12.155 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-16:38:13.169 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-16:45:32.256 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000914::2011/08/16-16:45:32.287 INFO  [GUM] Node 2: Processing RequestLock 3:571
  00000528.00000914::2011/08/16-16:45:32.287 INFO  [GUM] Node 2: Processing GrantLock to 3 (sent by 2 gumid: 44981)
  00000528.000004a8::2011/08/16-16:45:32.287 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44981.
  00000528.000004a8::2011/08/16-16:45:32.755 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44982.
  00000528.000005c0::2011/08/16-16:45:33.270 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-16:45:56.592 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000b3c::2011/08/16-16:45:57.091 INFO  [GUM] Node 2: Processing RequestLock 1:512
  00000528.00000914::2011/08/16-16:45:57.091 INFO  [GUM] Node 2: Processing GrantLock to 1 (sent by 3 gumid: 44983)
  00000528.000004a8::2011/08/16-16:45:57.091 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44983.
  00000528.000004a8::2011/08/16-16:45:57.559 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44984.
  00000528.000005c0::2011/08/16-16:45:57.606 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:45:58.620 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:45:59.634 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:00.648 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:01.662 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-16:46:01.818 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44985.
  00000528.000004a8::2011/08/16-16:46:02.192 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44986.
  00000528.000005c0::2011/08/16-16:46:02.676 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:03.690 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:04.704 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:05.718 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:06.732 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-16:46:06.763 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44987.
  00000528.000004a8::2011/08/16-16:46:07.106 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44988.
  00000528.000005c0::2011/08/16-16:46:07.746 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-16:46:08.760 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-16:46:08.885 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44989.
  00000528.000004a8::2011/08/16-16:46:09.243 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44990.
  00000528.000005c0::2011/08/16-16:46:09.774 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-16:53:11.598 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000928::2011/08/16-16:53:12.331 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-16:53:12.331 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-16:53:12.331 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-16:53:12.612 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:02:32.338 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000764::2011/08/16-17:02:32.509 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.000010dc::2011/08/16-17:02:32.509 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:02:32.509 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.000010dc::2011/08/16-17:02:32.509 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:02:33.352 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:02:34.366 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000764::2011/08/16-17:02:34.600 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.000008bc::2011/08/16-17:02:34.600 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:02:34.600 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.000008bc::2011/08/16-17:02:34.600 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000ce0.00000764::2011/08/16-17:02:35.286 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.000010dc::2011/08/16-17:02:35.286 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:02:35.286 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.000010dc::2011/08/16-17:02:35.302 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:02:35.380 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000764::2011/08/16-17:02:36.004 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.000008bc::2011/08/16-17:02:36.004 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:02:36.004 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.000008bc::2011/08/16-17:02:36.004 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:02:36.394 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:08:12.026 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000928::2011/08/16-17:08:12.338 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-17:08:12.338 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-17:08:12.338 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-17:08:13.040 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:15:32.110 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000914::2011/08/16-17:15:32.188 INFO  [GUM] Node 2: Processing RequestLock 3:573
  00000528.000004a8::2011/08/16-17:15:32.188 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44991.
  00000528.00000b3c::2011/08/16-17:15:32.484 INFO  [GUM] Node 2: Processing GrantLock to 3 (sent by 1 gumid: 44991)
  00000528.000004a8::2011/08/16-17:15:32.671 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44992.
  00000528.000005c0::2011/08/16-17:15:33.124 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:34.138 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:35.152 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:36.166 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:37.180 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:38.194 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:39.209 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:40.223 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:41.237 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:42.251 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:43.265 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000b3c::2011/08/16-17:15:44.217 INFO  [GUM] Node 2: Processing RequestLock 1:520
  00000528.00000914::2011/08/16-17:15:44.217 INFO  [GUM] Node 2: Processing GrantLock to 1 (sent by 3 gumid: 44993)
  00000528.000004a8::2011/08/16-17:15:44.217 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44993.
  00000528.000005c0::2011/08/16-17:15:44.279 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-17:15:44.560 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44994.
  00000528.000005c0::2011/08/16-17:15:45.293 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:46.308 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:47.322 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:48.336 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:49.350 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:50.364 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:51.378 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-17:15:51.581 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44995.
  00000528.000004a8::2011/08/16-17:15:51.940 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44996.
  00000528.000005c0::2011/08/16-17:15:52.392 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:53.407 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:15:54.421 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-17:15:55.419 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44997.
  00000528.000005c0::2011/08/16-17:15:55.435 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000004a8::2011/08/16-17:15:55.887 INFO  [GUM] Node 2: gum is shutting down. Ignoring gum /dm/update gumid 44998.
  00000528.000005c0::2011/08/16-17:15:56.449 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:18:05.245 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000764::2011/08/16-17:18:05.557 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.557 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:18:05.573 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.573 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000ce0.00000764::2011/08/16-17:18:05.573 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.573 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:18:05.588 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.588 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000ce0.00000764::2011/08/16-17:18:05.604 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.604 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000764::2011/08/16-17:18:05.604 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.00000b64::2011/08/16-17:18:05.604 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:18:06.259 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:23:11.497 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000928::2011/08/16-17:23:12.402 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-17:23:12.402 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-17:23:12.402 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-17:23:12.511 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:32:30.236 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000764::2011/08/16-17:32:30.439 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.0000134c::2011/08/16-17:32:30.439 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000d44::2011/08/16-17:32:30.439 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.0000134c::2011/08/16-17:32:30.439 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:32:31.250 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:32:32.265 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000d44::2011/08/16-17:32:32.483 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.00000920::2011/08/16-17:32:32.483 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000d44::2011/08/16-17:32:32.483 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.00000920::2011/08/16-17:32:32.483 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000ce0.00000d44::2011/08/16-17:32:33.185 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.0000134c::2011/08/16-17:32:33.185 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000d44::2011/08/16-17:32:33.185 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.0000134c::2011/08/16-17:32:33.185 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:32:33.279 INFO  [CS] Waiting for resources and groups to stop.
  00000ce0.00000d44::2011/08/16-17:32:33.872 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQ returned 21.'
  00000528.00000dc4::2011/08/16-17:32:33.872 WARN  [RCM] Failed to load restype 'MSMQ': error 21.
  00000ce0.00000d44::2011/08/16-17:32:33.872 ERR   [RHS] s_RhsRpcCreateResType: ERROR_NOT_READY(21)' because of 'Startup routine for ResType MSMQTriggers returned 21.'
  00000528.00000dc4::2011/08/16-17:32:33.872 WARN  [RCM] Failed to load restype 'MSMQTriggers': error 21.
  00000528.000005c0::2011/08/16-17:32:34.293 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:38:12.007 INFO  [CS] Waiting for resources and groups to stop.
  00000528.00000928::2011/08/16-17:38:12.491 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-17:38:12.491 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-17:38:12.491 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-17:38:13.021 INFO  [CS] Waiting for resources and groups to stop.

  00000528.000005c0::2011/08/16-17:41:18.599 INFO  [CS] Waiting for resources and groups to stop.
  00000528.000005c0::2011/08/16-17:41:18.599 ERR   [CS] It has taken too long for the service to stop. Exiting...
  00000528.000005c0::2011/08/16-17:41:18.599 INFO  [CORE] Node 2: Proposed View is <ViewChanged joiners=() downers=(2) newView=4202(1 3) oldView=4102(1 2 3) joiner=false form=false/>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO  [RGP] Node 2: Stable_`0 => Opening`1
  00000528.000005c0::2011/08/16-17:41:18.599 INFO  <class mscs::detail::ConsensusMessage>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <senderId> 2 </senderId>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <bestEpochSeen> 41 </bestEpochSeen>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <lastStableView> 4102(1 2 3) </lastStableView>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <proposedView> 4202(1 3) </proposedView>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <stage> Opening`1 </stage>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <inStage> () </inStage>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <inStagePrev> () </inStagePrev>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <joiners> (2) </joiners>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <trimmedNodes> (2) </trimmedNodes>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <innerScreen> (1 2 3) </innerScreen>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <pruningResult> (1 2 3) </pruningResult>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <matrix>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO      <ConnectivityMatrix>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO        <row id='0'00000000000000000000000000000000/>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO      </ConnectivityMatrix>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    </matrix>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO    <gemBlob> <counted_ptr p = 'nullptr'/> </gemBlob>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO  </class mscs::detail::ConsensusMessage>
  00000528.000005c0::2011/08/16-17:41:18.599 INFO  [RGP] Node 2: Just sent farewell regroup message
  00000528.00000910::2011/08/16-17:41:18.599 INFO  [RGP] Node 2: Timer Tick Started
  00000528.00000910::2011/08/16-17:41:18.911 INFO  [RGP] Node 2: Timer Tick Started
  00000528.000005c0::2011/08/16-17:41:19.113 INFO  [DM]: Shutting down, so unloading the cluster database.
  00000528.000005c0::2011/08/16-17:41:19.113 INFO  [DM] Shutting down, so unloading the cluster database (waitForLock: true).
  00000528.00000910::2011/08/16-17:41:19.223 INFO  [RGP] Node 2: Timer Tick Started
  00000528.000005c0::2011/08/16-17:41:19.269 INFO  [CS] Service Stopped...
  00000528.000005c0::2011/08/16-17:41:19.269 INFO  [CS] About to exit service...
  00000ce0.00000ce4::2011/08/16-17:41:19.285 WARN  [RHS] Cluster service has terminated.
  00000fdc.00000fd0::2011/08/16-17:41:19.285 WARN  [RHS] Cluster service has terminated.
  00000fdc.00001210::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk <Cluster Disk 2>: Close request for resource 'Cluster Disk 2'.
  00000fdc.00001108::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk <Cluster Disk 4>: Close request for resource 'Cluster Disk 4'.
  00000fdc.00000edc::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk <Cluster Disk 1>: Close request for resource 'Cluster Disk 1'.
  00000fdc.0000034c::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk <Cluster Disk 3>: Close request for resource 'Cluster Disk 3'.
  00000fdc.00000e64::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk <Cluster Disk 5>: Close request for resource 'Cluster Disk 5'.
  00000fdc.00001054::2011/08/16-17:41:19.285 INFO  [RES] Physical Disk: PNP: Watcher thread exititng, status 0
  00000fdc.000010f4::2011/08/16-17:41:19.285 INFO  [RES] IP Address <Cluster IP Address>: IpaClose entry
  00000fdc.000010f4::2011/08/16-17:41:19.285 INFO  [RES] IP Address <Cluster IP Address>: IpaReleaseResource entry
  00000fdc.00000ce8::2011/08/16-17:41:19.285 INFO  [RES] Network Name <Cluster Name>: Stopping credential update threads
  00000fdc.00000ce8::2011/08/16-17:41:19.285 WARN  [RES] Network Name <Cluster Name>: Trying to remove credentials for LocalSystem returned status C0000225, STATUS_NOT_FOUND is a non-critical failure for a remove operation
  00000ce0.00000ce4::2011/08/16-17:41:19.285 INFO  [RHS] Exiting.
  00000fdc.00000fd0::2011/08/16-17:41:19.285 INFO  [RHS] Exiting.

  Tuesday, August 16, 2011 6:37 PM
• 

  

  0

  Sign in to vote

  Just for comparison rebooting with the Cluster service already stopped:

  2:45:13 PM - Restart Request
  2:45:27 PM - Eventlog stopped
  2:45:30 PM - Kernel Shutdown
  2:53:37 PM - Kernel Start
  2:53:51 PM - Eventlog started

  Less than 1 minute to shutdown and less than 9 for entire cycle.  Instead of 70-80 minutes total.

  Tuesday, August 16, 2011 7:00 PM
• 

  

  0

  Sign in to vote

  OK, since we are in a testing mode and you can do this in your environment, let's try doing reboots at intervals.  For example, let's use the node on which you saw this problem:

  1.  After the most recent reboot, move some workloads back to the node.

  2.  After 2 hours, place the node in Maintenance Mode again and then reboot the node.  What is the delay?

  3.  If step #2 is reasonable from your perspective, setup another test but this time wait 6 hours before trying the test.

  My point is that there may be a resource issue here.  Can you also post the version for clussvc.exe?

  Thanks.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  Tuesday, August 16, 2011 7:13 PM
• 

  

  0

  Sign in to vote

  clussvc - 6.1.7601.21639

  Before trying your steps I wanted to try and even smaller test.  After the previous shut down I rebooted with the cluster service disabled.  (I am trying to do windows updates / drivers / storage manager so I need to reboot a few times.)  I then started the service manually.  Installed updated storage manager.  Then tried to stop it manually again.  This was about a 20 minute span and I didn't move any resources to this server in the meantime.  It is still stuck again. 

  It appears I just need to start the service to then get it stuck again?  Also for some reason this time I had some CSV access issues.  I am wondering if that was due to booting with cluster service disabled, since those are new.  I tried to post log but I guess it is too long as the server keeps timing out on submit.

  Tuesday, August 16, 2011 7:51 PM
• 

  

  0

  Sign in to vote

  Just shut down, almost exactly 68 minutes again?

  Tuesday, August 16, 2011 8:54 PM
• 

  

  0

  Sign in to vote

  I will do some more internal investigation.  The latest version of the file is associated with this - http://support.microsoft.com/kb/2575625

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  Tuesday, August 16, 2011 9:38 PM
• 

  

  0

  Sign in to vote

  I installed that hotfix and tested it, still another hour +.  I need to move on to my other nodes tomorrow so I will update if they have similar issue, I think the answer is yes from recent experience though.

  Wednesday, August 17, 2011 1:16 AM
• 

  

  0

  Sign in to vote

  Do this for me...on all your resource groups, remove Preferred Owner configurations and any Failback policies currently implemented and then test.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  • Marked as answer by Chuck Timon [MSFT]Microsoft employee Monday, August 22, 2011 10:57 AM
  • Unmarked as answer by Elden ChristensenMicrosoft employee Sunday, January 20, 2013 4:20 PM

  Wednesday, August 17, 2011 1:32 AM
• 

  

  0

  Sign in to vote

  Well that seemed to work, cluster service now shuts down in seconds?  I guess the question now is why?  Can prefferred owners and failback not be used?  Thanks for your help on this.

  Wednesday, August 17, 2011 12:28 PM
• 

  

  0

  Sign in to vote

  Well, that is great to hear.  So, tell me a little about your Preferred Owner configuration and your Failback Policy settings.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  Wednesday, August 17, 2011 1:07 PM
• 

  

  0

  Sign in to vote

  I have a three node cluster.  Two of the nodes are R610 and one is a 2900.  One of the R610 has more / newer / faster processors so I try to keep my more proc intensive VM on it.  The 2900 is considerably slower so I try to shift low Proc VM to it.  I had set each resource to have a single preffered owner and then a fallback of 2-4 hours.  I thought this would be a handy way to get the VM auto positioned after maintenance or power outage rahter than manually shifting everything around.  It seemed to work great other than the cluster service timeout.  Any other details I can share?

  Wednesday, August 17, 2011 1:25 PM
• 

  

  0

  Sign in to vote

  OK, so each VM Group has a Node in the cluster set as a Preferred Owner.  This statement "and then a fallback of 2-4 hours" is not clear and I think you may misunderstand the setting.  The setting really means to Failback between 2 and 4 a.m. in the morning  (http://support.microsoft.com/kb/197047) not 2-4 hours after a Failover has occurred.  With respect to HA Virtual Machine Groups, there is also the Persisten Mode setting which is enabled by default for this type of group (more info here - http://blogs.msdn.com/b/clustering/archive/2009/08/11/9864574.aspx) but Preferred Owners take precedence over this setting.  Also, keep in mind that Preferred Owners and Failback Policies only come into effect for a Failure.  In reference to your statement above, only a power outage (without UPS kick in) would be a failure and not maintenence which implies a controlled move of resource groups.

  One thing that is confusing is that in the cluster logs you have posted I noted this -

  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedMailData Resources.
  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedSQL2010 Resources.
  00000528.00000928::2011/08/16-16:38:12.296 INFO  [RCM] Failback: will try again later for group SCVMM RedShare2010 Resources.
  00000528.000005c0::2011/08/16-16:38:13.169 INFO  [CS] Waiting for resources and groups to stop.

  The assumption was the last test you conducted where you posted a cluster log was the node being tested was totally passive meaning it was hosting no resource groups which means we should not have seen something like this in the cluster log from the node being tested. Or, it could just be an artifact that popped up in your testing becasue a proper procedure was not executed.  Let's try this:

  1.  Re-implement your Preferred Owner list and the Failback Policy.

  2.  Select a node for testing and let's pretend it is a Maintenance window for this node, so move all the resoruce groups off the node (Don't forget the Core Cluster Resource Group which must be moved via command line (cluster . group "cluster Group" /move) and then Pause that node.

  3.  Now try stopping the cluster service and see what the behavior is.

  4.  If the bad behavior returns, open Task Manager, select the Processes tab, find clussvc.exe, Right-Clck and select Create Dump File.

  5.  Open a case with us and send the dump file for analysis.

  Thanks.

  Chuck

   

   

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Microsoft Corporation

  Wednesday, August 17, 2011 2:43 PM
• 

  

  0

  Sign in to vote

  I want to clarify the failback setting because nowhere does it say AM / PM it only says hours?  If I right click on the Cluster Resource and choose properties.  It brings up a window with two tabs General and Failover.  On the Failover tab it has a section called Failback.  I had selected the Allow Failback and then Failback between 2 and 4 hours.  Are you saying that rather than a time span of hours as the GUI indicates it is actually a time of day?  Does the 197047 KB apply to 2008 / R2 since it was last updated in 2007 before 2008 was released?

  The failback procedure worked perfectly for me when I took a node out of maintenance mode.  A few hours later all the Cluster resources automatically moved back to their preferred owners.  The persistent owner won't work exactly the way I want since if after a power outage one node powers up faster it will be the default node for that VM, which isn't always what I want.

  In the logs I believe the failback was attempting to occur based on the settings I mentioned above.  The cluster was attempting to move the resource back to the preferred owner automatically?  At the time the logs were done the node was hosting nothing but I hadn't yet cleared the preferred owners as you suggested this morning.

   

  Wednesday, August 17, 2011 3:01 PM
• 

  

  0

  Sign in to vote

  The concepts in the KB still applies and it is a 24 hour clock just like the military.

  When you configure a group to automatically failback to the preferred node, you specify whether you want the group to failback as soon as the preferred node is available or to failback only during specific hours that you define. This option is useful if you want the failback to occur after peak business hours, or if you want to make sure the preferred node is able to support the group when it does come back online.
  
  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Windows Beta Engineer Microsoft Corporation

  Wednesday, August 17, 2011 4:43 PM
• 

  

  0

  Sign in to vote

  Let's try this:

  1.  Re-implement your Preferred Owner list and the Failback Policy.

  2.  Select a node for testing and let's pretend it is a Maintenance window for this node, so move all the resoruce groups off the node (Don't forget the Core Cluster Resource Group which must be moved via command line (cluster . group "cluster Group" /move) and then Pause that node.

  3.  Now try stopping the cluster service and see what the behavior is.

  4.  If the bad behavior returns, open Task Manager, select the Processes tab, find clussvc.exe, Right-Clck and select Create Dump File.

  5.  Open a case with us and send the dump file for analysis.

  Thanks.

  Chuck

  I went and added the preferred owner and failback only for those VM I want to be on the node that I am testing on.  The problem came back and I am stuck with a long shutdown time.  I have created a dump file and will have to see about creating a case since I would have to pay for it.  For now I will just disable the preferred owner settings to prevent the 68 minute timeout issue.

  Wednesday, August 17, 2011 5:18 PM
• 

  

  0

  Sign in to vote

  OK.  Sounds like a plan.  I have engaged others internally and will see if they have any other ideas that I can pass on.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Windows Beta Engineer Microsoft Corporation

  Wednesday, August 17, 2011 5:31 PM
• 

  

  0

  Sign in to vote

  Run this cmdlet on one of the nodes Get-Cluster | fl * and get me the value for ShutdownTimeoutInMinutes

  Thanks.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Windows Beta Engineer Microsoft Corporation

  Thursday, August 18, 2011 6:27 PM
• 

  

  0

  Sign in to vote

  74?

  Brian

  Thursday, August 18, 2011 6:32 PM
• 

  

  0

  Sign in to vote

  Really?  Not good.  Default setting is 20.  Now the question is, who changed it and why.

  Chuck

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Windows Beta Engineer Microsoft Corporation

  Thursday, August 18, 2011 6:47 PM
• 

  

  0

  Sign in to vote

  Well the only person who has access to make changes to this cluster is me.  I built it from scratch with 2008 R2 RTM media in August 2009.  I can't recall changing it on purpose.  I can't explain it otherwise.  Can I change it?  How?  Any reason not to?  These are pretty vanilla servers basically running Hyper-V / Cluster with SCDPM / SCVMM agents and drivers.  Nothing else installed on them other than SP1 and other WU / Hotfix.

  Thursday, August 18, 2011 6:52 PM
• 

  

  2

  Sign in to vote

  Here is an example:

  Get-Cluster <name of your cluster> | %{$_.ShutDownTimeOutInMinutes=10}

  That changes the value to 10 minutes.

  Chuck

   

   

  ---

  Chuck Timon Senior, Support Escalation Engineer (SEE) Windows Beta Engineer Microsoft Corporation

  • Marked as answer by Brian Hoyt Wednesday, March 21, 2012 7:46 PM

  Thursday, August 18, 2011 7:05 PM
• 

  

  1

  Sign in to vote

  Hi.

  I've just stumbled upon a MSDN article which explain WHO is changing the default shutdown timeout. It's Hyper-V:

  *** Note If the Hyper-V role is installed, the default time-out value is calculated based on the size of physical memory, using a ratio of 100 minutes / 64 GB. The minimum computed value is 20 minutes.

  http://msdn.microsoft.com/en-us/library/ee342507(VS.85).aspx

   

  But for me a big question is: Why is the cluster waiting for resources and groups on shutdown when there are none on that node.

  I've run into that issue in the past some times, and even if I completely clean the nodes manually of any resource and groups, including "Cluster Group" and "Availabe Storage" it could happen that this node run into the shutdown time out.....

  Olaf

  • Marked as answer by Brian Hoyt Wednesday, March 21, 2012 7:46 PM

  Monday, September 12, 2011 10:28 AM
• 

  

  0

  Sign in to vote

  Hi,

  check out KB2673129.

  Slow shutdown time for a cluster node in a Windows Server 2008 R2-based cluster

  http://support.microsoft.com/default.aspx?scid=kb;EN-US;2673129
  

  Regards,

  Alex.

  
  

  • Marked as answer by Elden ChristensenMicrosoft employee Sunday, January 20, 2013 4:08 PM

  Friday, March 30, 2012 9:33 AM
• 

  

  0

  Sign in to vote

  This solved my problem.  Thanks!

  Friday, January 18, 2013 6:42 PM