So I went to do a standard rolling upgrade last week of our production x64 2003 SQL cluster to windows 2003 SP2... Not so standard after all... Our MS TAM is investigating to see if this is an isolated issue, but here's what happened for us.
Here’s the technical details of the cluster and the upgrade:
· Windows 2003 R2 x64
· Standard Quorum Failover cluster with SAN disk
· Was at Windows 2003 SP1 – Rolling upgrade attempted to SP2
· Cluster service would not start after SP2 and a reboot. Issued a number of SCSI bus resets because of communication failure
· No problems with network communication between heartbeat adapters or public adapters (public adapters are Mixed-Mode as per best-practices)
· SP2 node cluster service would come online with no errors if it was the first node (but then the SP1 would not join)
· Once they were both SP2, there were no problems joining the cluster at all
Here’s an excerpt from the Cluster Log of the service trying to come online with a couple notes from me (Sorry this is long, but it is good stuff, especially if you are not familiar with the cluster log):
00000384.00000c78::2007/08/31-00:30:04.171 INFO [CS] Cluster Service started - Cluster Node Version 4.379000000384.00000c78::2007/08/31-00:30:04.171 INFO OS Version 5.2.3790 - Service Pack 2 (ADS 03000112L)00000384.00000c78::2007/08/31-00:30:04.171 INFO Local Time is 2007/08/30-18:30:04.17100000384.00000ba4::2007/08/31-00:30:04.187 INFO [CS] Service Starting...00000384.00000ba4::2007/08/31-00:30:04.187 INFO [INIT] ClusterInitialize called to start cluster.00000384.00000ba4::2007/08/31-00:30:04.187 INFO [EP] Initialization...00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] Initialization00000384.00000ba4::2007/08/31-00:30:04.187 ERR [DM] DmInitialize: The hive was loaded- rollback, unload and reload again00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] DmpRestartFlusher: Entry00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] DmpUnloadHive: unloading the hive00000384.00000ba4::2007/08/31-00:30:04.187 INFO [Qfs] QfsSetFileAttributes C:\WINDOWS\Cluster\CLUSDB.BKP$ 80, status 200000384.00000ba4::2007/08/31-00:30:04.187 INFO [Qfs] QfsDeleteFile C:\WINDOWS\Cluster\CLUSDB.BKP$, status 200000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] Loading cluster database from C:\WINDOWS\Cluster\CLUSDB00000384.00000ba4::2007/08/31-00:30:04.203 INFO [DM] DmpStartFlusher: Entry00000384.00000ba4::2007/08/31-00:30:04.203 INFO [DM] DmpStartFlusher: thread created00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Initializing...00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Local node name = CLUSTERNODE1.00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Local node ID = 1.00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Creating object for node 1 (CLUSTERNODE1)00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Initializing networks.00000384.00000ba4::2007/08/31-00:30:04.203 INFO [NM] Initializing network interfaces.00000384.00000ba4::2007/08/31-00:30:04.218 WARN [NM] Failed to open cluster parameters key, status 2.00000384.00000ba4::2007/08/31-00:30:04.218 INFO [NM] Initialization complete.00000384.00000ba4::2007/08/31-00:30:04.218 INFO [FM] Starting worker thread...00000384.00000ba4::2007/08/31-00:30:04.218 INFO [API] Initializing00000384.00000ba4::2007/08/31-00:30:04.218 INFO [LM] LmInitialize Entry. 00000384.00000ba4::2007/08/31-00:30:04.218 INFO [LM] TimerActInitialize Entry. 00000384.00000d50::2007/08/31-00:30:04.218 INFO [FM] Worker thread running00000384.00000ba4::2007/08/31-00:30:04.218 INFO [CS] Service Domain Account = Domain\ServiceAccount00000384.00000ba4::2007/08/31-00:30:04.218 INFO [CS] Initializing RPC server.00000384.00000ba4::2007/08/31-00:30:04.218 INFO [INIT] CspRegisterDynamicLRPCEndpoint: Successfully registered LRPC endpoint with EP mapper00000384.00000ba4::2007/08/31-00:30:04.218 INFO [INIT] Attempting to join cluster CLUSTERNETNAME00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.97.130.14100000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.255.255.14300000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.101.130.14100000384.00000cd4::2007/08/31-00:30:04.218 INFO [JOIN] Asking 10.255.255.143 to sponsor us after delay of 0 milliseconds.00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor CLUSTERNODE200000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.97.130.14200000384.00000cd4::2007/08/31-00:30:04.234 WARN [JOIN] Unable to get join version data from sponsor 10.255.255.143 using NTLM package, status 5. This seems to be the failure point. It looks like the version data for the “Join” command was invalid (from SP1 to SP2). The next couple of errors are the retries.
00000384.00000cd4::2007/08/31-00:30:04.234 WARN [JOIN] JoinVersion data for sponsor 10.255.255.143 is invalid, status 5.00000384.000005d8::2007/08/31-00:30:05.218 INFO [JOIN] Asking CLUSTERNODE2 to sponsor us after delay of 1000 milliseconds.00000384.00000d18::2007/08/31-00:30:05.218 INFO [JOIN] Asking 10.101.130.141 to sponsor us after delay of 1000 milliseconds.00000384.00000cd8::2007/08/31-00:30:05.218 INFO [JOIN] Asking 10.97.130.141 to sponsor us after delay of 1000 milliseconds.00000384.00000cd8::2007/08/31-00:30:05.218 WARN [JOIN] Unable to get join version data from sponsor 10.97.130.141 using NTLM package, status 5.00000384.00000cd8::2007/08/31-00:30:05.218 WARN [JOIN] JoinVersion data for sponsor 10.97.130.141 is invalid, status 5.00000384.000005d8::2007/08/31-00:30:05.218 WARN [JOIN] Unable to get join version data from sponsor CLUSTERNODE2 using NTLM package, status 5.00000384.000005d8::2007/08/31-00:30:05.218 WARN [JOIN] JoinVersion data for sponsor CLUSTERNODE2 is invalid, status 5.00000384.00000730::2007/08/31-00:30:06.218 INFO [JOIN] Asking 10.97.130.142 to sponsor us after delay of 2000 milliseconds.00000384.00000730::2007/08/31-00:30:06.218 WARN [JOIN] Unable to get join version data from sponsor 10.97.130.142 using NTLM package, status 5.00000384.00000730::2007/08/31-00:30:06.218 WARN [JOIN] JoinVersion data for sponsor 10.97.130.142 is invalid, status 5.00000384.00000d18::2007/08/31-00:30:37.218 INFO [JOIN] Sponsor 10.101.130.141 is not available (JoinVersion), status=1722.00000384.00000d18::2007/08/31-00:30:37.218 WARN [JOIN] JoinVersion data for sponsor 10.101.130.141 is invalid, status 1722.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [JOIN] Got out of the join wait, CsJoinThreadCount = 1.00000384.00000ba4::2007/08/31-00:30:37.218 ERR [JOIN] Unable to connect to any sponsor node.00000384.00000ba4::2007/08/31-00:30:37.218 WARN [INIT] Failed to join cluster, status 53 At this point the node is assuming that the cluster is down because it could not correctly communicate, so it will try to create the cluster by forcing the quorum disk online. These all fail, as the other node is actively locking those disks, so they cannot be released. This is behavior by design.
00000384.00000ba4::2007/08/31-00:30:37.218 INFO [INIT] Attempting to form cluster CLUSTERNETNAME00000384.00000ba4::2007/08/31-00:30:37.218 INFO [API] Online read only00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Creating group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef7200000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Initializing group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72 from the registry.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Name for Group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72 is 'ClusterNetName - MSCS'.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72 contains Resource 6dca06aa-84ec-4ded-bc2e-3079612f4533.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Creating resource 6dca06aa-84ec-4ded-bc2e-3079612f453300000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Initializing resource 6dca06aa-84ec-4ded-bc2e-3079612f4533 from the registry.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Name for Resource 6dca06aa-84ec-4ded-bc2e-3079612f4533 is 'Cluster IP Address'.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleEntry: adding node 1 as possible host for resource 6dca06aa-84ec-4ded-bc2e-3079612f4533.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpQueryResTypeInfo: Calling FmpAddPossibleNodeToList for restype IP Address00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] All dependencies for resource 6dca06aa-84ec-4ded-bc2e-3079612f4533 created.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72 contains Resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Creating resource 70e2212b-e8bd-49bd-aa27-ae3c14e9976200000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Initializing resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762 from the registry.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Name for Resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762 is 'Cluster Name'.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleEntry: adding node 1 as possible host for resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpQueryResTypeInfo: Calling FmpAddPossibleNodeToList for restype Network Name00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762 depends on 6dca06aa-84ec-4ded-bc2e-3079612f4533. Creating...00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] CreateResource, Opened existing resource 6dca06aa-84ec-4ded-bc2e-3079612f453300000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] All dependencies for resource 70e2212b-e8bd-49bd-aa27-ae3c14e99762 created.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72 contains Resource c3aea6d9-2a3d-48e9-80a5-18421c028341.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Creating resource c3aea6d9-2a3d-48e9-80a5-18421c02834100000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Initializing resource c3aea6d9-2a3d-48e9-80a5-18421c028341 from the registry.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Name for Resource c3aea6d9-2a3d-48e9-80a5-18421c028341 is 'Disk Q:'.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleEntry: adding node 1 as possible host for resource c3aea6d9-2a3d-48e9-80a5-18421c028341.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpQueryResTypeInfo: Calling FmpAddPossibleNodeToList for restype Physical Disk00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Found the quorum resource c3aea6d9-2a3d-48e9-80a5-18421c028341.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] All dependencies for resource c3aea6d9-2a3d-48e9-80a5-18421c028341 created.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Arbitrate for quorum resource id c3aea6d9-2a3d-48e9-80a5-18421c028341.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Initializing resource c3aea6d9-2a3d-48e9-80a5-18421c028341 from the registry.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Name for Resource c3aea6d9-2a3d-48e9-80a5-18421c028341 is 'Disk Q:'.00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpRmCreateResource: creating resource c3aea6d9-2a3d-48e9-80a5-18421c028341 in shared resource monitor00000d28.00000d94::2007/08/31-00:30:37.218 INFO [RM] Main: Initializing.00000d28.00000d94::2007/08/31-00:30:37.218 INFO [RM] RmpGetDynamicEndpointName: Successfully got LRPC endpoint info, EP name is LRPC00000d28.0000000100000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Resmon LRPC EP name is LRPC00000d28.0000000100000384.00000c84::2007/08/31-00:30:37.218 INFO [FM] Calling RmNotifyChanges in monitor 0d28.00000d28.00000e3c::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] Waiting for PnP interface registration to complete.00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] PnP window created successfully.00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\fdc#generic_floppy_drive#6&211ce946&0&0#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Skipping floppy volume \\?\Volume{c6dc1c17-242a-11dc-8ad3-c73f05f62cd6}\00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\fdc#generic_floppy_drive#6&211ce946&0&0#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} - processed 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\ide#cdromhl-dt-st_dvd-rom_gdr-d10n_______________3.00____#5&2270d2f8&0&0.0.0#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Skipping CDROM volume \\?\Volume{c6dc1c16-242a-11dc-8ad3-806e6f6e6963}\00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\ide#cdromhl-dt-st_dvd-rom_gdr-d10n_______________3.00____#5&2270d2f8&0&0.0.0#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} - processed 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\storage#volume#1&30a96598&0&signature269b269boffset4000length8787ec000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Attempting to add volume \\?\Volume{c6dc1c15-242a-11dc-8ad3-806e6f6e6963}\00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: adding volume \??\Volume{c6dc1c15-242a-11dc-8ad3-806e6f6e6963}00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: \\?\storage#volume#1&30a96598&0&signature269b269boffset4000length8787ec000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 'C', 7 (1052176)00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Online request not queued for signature 269b269b00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\storage#volume#1&30a96598&0&signature269b269boffset4000length8787ec000#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} - processed 00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] PnP interface registration complete.00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] Setting PnP interface registration event.00000d28.00000184::2007/08/31-00:30:37.250 INFO Physical Disk: [PnP] NotifierThread is waiting for messages.00000384.00000ba4::2007/08/31-00:30:37.250 INFO [FM] FmpRmCreateResource: created resource c3aea6d9-2a3d-48e9-80a5-18421c028341, resid 131363200000384.00000ba4::2007/08/31-00:30:37.250 INFO [MM] MmSetQuorumOwner(1,1), old owner 0.00000384.00000ba4::2007/08/31-00:30:37.250 INFO [FM] Set membership mask of 0x0 returns status 100000d28.00000e3c::2007/08/31-00:30:37.250 INFO Physical Disk <Disk Q:>: [DiskArb] Wait for offline thread to complete...00000d28.00000e3c::2007/08/31-00:30:37.250 INFO Physical Disk <Disk Q:>: [DiskArb]------- DisksArbitrate -------.00000d28.00000e3c::2007/08/31-00:30:37.250 INFO Physical Disk <Disk Q:>: [DiskArb] DisksOpenResourceFileHandle: Attaching to disk with signature 9e1c3236 00000d28.00000e3c::2007/08/31-00:30:37.250 INFO Physical Disk <Disk Q:>: [DiskArb] DisksOpenResourceFileHandle: Disk unique id present trying new attach00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] DisksOpenResourceFileHandle: Retrieving disk number from ClusDisk registry key 00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] DisksOpenResourceFileHandle: Retrieving handle to PhysicalDrive1 00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] DisksOpenResourceFileHandle: Returns success.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitration Parameters: ArbAttempts 5, SleepBeforeRetry 500 ms.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Read disk geometry to get the sector size.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetSectorSize on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] GetSectorSize completed, status 0.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] ArbitrationInfo.SectorSize is 51200000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info to insure the disk is accessible.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate for ownership of the disk by reading/writing various disk sectors.00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] Successful read (sector 12) [CLUSTERNODE2:64830] (0,a4f8bd6e:01c7e8b1).00000d28.00000e3c::2007/08/31-00:30:41.250 INFO Physical Disk <Disk Q:>: [DiskArb] No reservation found. Read'n'wait.00000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\STORAGE#Volume#1&30a96598&0&Signature9E1C3236Offset7E00Length3FBB8600#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 00000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: Attempting to add volume \\?\Volume{32b79673-2435-11dc-bb9d-806e6f6e6963}\00000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: adding volume \??\Volume{32b79673-2435-11dc-bb9d-806e6f6e6963}00000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: \\?\STORAGE#Volume#1&30a96598&0&Signature9E1C3236Offset7E00Length3FBB8600#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} 'Q', 7 (1049568)00000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: Online request not queued for signature 000000d28.00000184::2007/08/31-00:30:41.250 INFO Physical Disk: [PnP] AddVolume: Adding Name \\?\STORAGE#Volume#1&30a96598&0&Signature9E1C3236Offset7E00Length3FBB8600#{53f5630d-b6bf-11d0-94f2-00a0c91efb8b} - processed 00000d28.00000e3c::2007/08/31-00:30:48.250 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to read (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:30:48.750 WARN Physical Disk <Disk Q:>: [DiskArb] Retry arbitration, 4 attempts left 00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info to insure the disk is accessible.00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate for ownership of the disk by reading/writing various disk sectors.00000d28.00000e3c::2007/08/31-00:30:48.750 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to read (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] We are about to break reserve.00000d28.00000e3c::2007/08/31-00:30:48.750 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing BusReset on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:50.843 INFO Physical Disk <Disk Q:>: [DiskArb] BusReset completed, status 0.00000d28.00000e3c::2007/08/31-00:30:52.843 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info from the disk to insure disk is accessible.00000d28.00000e3c::2007/08/31-00:30:52.843 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:53.843 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:30:53.843 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to write (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:30:54.343 WARN Physical Disk <Disk Q:>: [DiskArb] Retry arbitration, 3 attempts left 00000d28.00000e3c::2007/08/31-00:30:54.343 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info to insure the disk is accessible.00000d28.00000e3c::2007/08/31-00:30:54.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:54.343 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:30:54.343 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate for ownership of the disk by reading/writing various disk sectors.00000d28.00000e3c::2007/08/31-00:30:55.343 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to read (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:30:55.343 INFO Physical Disk <Disk Q:>: [DiskArb] We are about to break reserve.00000d28.00000e3c::2007/08/31-00:30:55.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing BusReset on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:30:57.343 INFO Physical Disk <Disk Q:>: [DiskArb] BusReset completed, status 0.00000d28.00000e3c::2007/08/31-00:30:59.343 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info from the disk to insure disk is accessible.00000d28.00000e3c::2007/08/31-00:30:59.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:00.343 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:31:01.343 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to write (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:31:01.843 WARN Physical Disk <Disk Q:>: [DiskArb] Retry arbitration, 2 attempts left 00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info to insure the disk is accessible.00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate for ownership of the disk by reading/writing various disk sectors.00000d28.00000e3c::2007/08/31-00:31:01.843 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to read (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] We are about to break reserve.00000d28.00000e3c::2007/08/31-00:31:01.843 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing BusReset on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:03.843 INFO Physical Disk <Disk Q:>: [DiskArb] BusReset completed, status 0.00000d28.00000e3c::2007/08/31-00:31:05.843 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info from the disk to insure disk is accessible.00000d28.00000e3c::2007/08/31-00:31:05.843 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:06.843 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:31:06.843 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to write (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:31:07.343 WARN Physical Disk <Disk Q:>: [DiskArb] Retry arbitration, 1 attempts left 00000d28.00000e3c::2007/08/31-00:31:07.343 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info to insure the disk is accessible.00000d28.00000e3c::2007/08/31-00:31:07.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:07.343 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:31:07.343 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate for ownership of the disk by reading/writing various disk sectors.00000d28.00000e3c::2007/08/31-00:31:08.343 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to read (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:31:08.343 INFO Physical Disk <Disk Q:>: [DiskArb] We are about to break reserve.00000d28.00000e3c::2007/08/31-00:31:08.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing BusReset on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:10.343 INFO Physical Disk <Disk Q:>: [DiskArb] BusReset completed, status 0.00000d28.00000e3c::2007/08/31-00:31:12.343 INFO Physical Disk <Disk Q:>: [DiskArb] Read the partition info from the disk to insure disk is accessible.00000d28.00000e3c::2007/08/31-00:31:12.343 INFO Physical Disk <Disk Q:>: [DiskArb] Issuing GetPartInfo on signature 9e1c3236.00000d28.00000e3c::2007/08/31-00:31:13.343 INFO Physical Disk <Disk Q:>: [DiskArb] GetPartInfo completed, status 0.00000d28.00000e3c::2007/08/31-00:31:14.343 ERR Physical Disk <Disk Q:>: [DiskArb] Failed to write (sector 12), error 170.00000d28.00000e3c::2007/08/31-00:31:14.343 INFO Physical Disk <Disk Q:>: [DiskArb] Arbitrate returned status 170. At this point, the service has recognized that it cannot force control of the Quorum disk, either because it is online of because of a system failure, and it initializes the service shutdown procedures.
00000384.00000ba4::2007/08/31-00:31:14.343 INFO [MM] MmSetQuorumOwner(0,0), old owner 1.00000384.00000ba4::2007/08/31-00:31:14.343 ERR [FM] FmGetQuorumResource failed, error 170.00000384.00000ba4::2007/08/31-00:31:14.343 ERR [INIT] ClusterForm: Could not get quorum resource. No fixup attempted. Status = 508600000384.00000ba4::2007/08/31-00:31:14.343 INFO [INIT] Cleaning up failed form attempt.00000384.00000ba4::2007/08/31-00:31:14.343 ERR [INIT] Failed to form cluster, status 5086.00000384.00000ba4::2007/08/31-00:31:14.343 ERR [CS] ClusterInitialize failed 508600000384.00000ba4::2007/08/31-00:31:14.343 WARN [INIT] The cluster service is shutting down.00000384.00000ba4::2007/08/31-00:31:14.343 INFO [EVT] EvShutdown00000384.00000ba4::2007/08/31-00:31:14.343 WARN [FM] Shutdown: Failover Manager requested to shutdown groups.00000384.00000ba4::2007/08/31-00:31:14.343 INFO [FM] FmpCleanupGroups: Entry00000384.00000ba4::2007/08/31-00:31:14.343 INFO [FM] FmpCleanupGroups: Exit00000384.00000ba4::2007/08/31-00:31:14.343 INFO [Dm] DmShutdown00000384.00000ba4::2007/08/31-00:31:14.343 INFO [DM] DmpShutdownFlusher: Entry00000384.00000ba4::2007/08/31-00:31:14.343 INFO [DM] DmpShutdownFlusher: Setting event00000384.00000e24::2007/08/31-00:31:14.343 INFO [DM] DmpRegistryFlusher: got 000000384.00000e24::2007/08/31-00:31:14.343 INFO [DM] DmpRegistryFlusher: exiting00000384.00000ba4::2007/08/31-00:31:14.343 WARN [MM] MMLeave is called when rgp=NULL.00000384.00000ba4::2007/08/31-00:31:14.343 ERR [CS] Service Stopped. exit code = 508600000d28.00000d94::2007/08/31-00:31:14.562 WARN [RM] Going away, Status = 1, Shutdown = 0.00000d28.00000d94::2007/08/31-00:31:14.562 ERR [RM] Active Resource = 0000000000000d28.00000d94::2007/08/31-00:31:14.562 ERR [RM] Resource State is 1, ""00000d28.00000d94::2007/08/31-00:31:14.562 INFO [RM] Posting shutdown notification.00000d28.00000c5c::2007/08/31-00:31:14.562 INFO [RM] NotifyChanges shutting down.00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: Terminate, ResourceEntry @ 00000000000F33E0 Valid 0 00000d28.00000184::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: [PnP] Stop watching PnP events for disk 9e1c323600000d28.00000184::2007/08/31-00:31:15.062 WARN Physical Disk <Disk Q:>: [PnP] RemoveDisk: WatchedList is empty 00000d28.00000184::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: [PnP] Stop watching disk 9e1c3236 - processed 00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: DiskCleanup started.00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: [DiskArb] StopPersistentReservations is called.00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: [DiskArb] StopPersistentReservations is complete.00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: DiskCleanup returning final error 0 00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: DisksMountPointCleanup: Cleanup mount point information 00000d28.00000d94::2007/08/31-00:31:15.062 INFO Physical Disk <Disk Q:>: [DiskArb] ArbitrationInfoCleanup.00000d28.000004c8::2007/08/31-00:31:15.062 INFO [RM] RmpPollerThread: Asked to exit...00000d28.000004c8::2007/08/31-00:31:15.062 INFO [RM] PollerThread stopping. Shutdown = 1, Status = 1, WaitFailed = 0, NotifyEvent address = 288.