in

SharePoint Blogs

The Best Place for SharePoint-related Blogs

echef

From the cluttered (and clustered) brain of Josef Nielsen... A great place for Food, Friends, and... uh... SharePoint of course!

September 2007 - Posts

  • Background on My SharePoint Links

    So recently we had some issues that came up around the "My SharePoint Links" option that exists on default master pages under the menu option "My Links".  Our issue was that a few sites never showed up on that list for some people during testing.  This spawned a number of questions about this process, which I decided to share, as I couldn't find much on the Internet currently about this.  This is the information I've found, seen, and some is my best guess, based on the behavior of the system. 

    When My SharePoint Sites shows up

    My SharePoint Links only shows up when you have multiple Site Collections.  If you are working with one Site Collection, the list item for these links will not appear.  After adding another collection, there is a waiting/polling period before it appears.  This seems to be 5-30 minutes usually.  My best guess is that this is linked to an sptimer job, although I haven't found information on that yet.  This appears to be the same job that "converts" a new site to standard security objects (see below).

    Which Sites show up on the My SharePoint Sites list

    So which sites belong on that list?  Any site for which the current logged in user is in the configured "Members" group.  Owners, Admins, and Visitors make no difference for this list, only Members.  This is the same list that is populated on MySites in the profile section labeled "Memberships".  You can manage these at http://<mysite_root_url>/_layouts/MyMemberships.aspx...

    How security is setup originally

    As far as I've been able to tell, any given site, when created, contains a custom list for security that is not linked to actual security objects.  It does seem to link to AD security principles (the "Account" field), but the rest on the information is just standard editable fields (see screen shot below).   

     New Site Security Columns 

    You can get to this first screen by adding _layouts/people.aspx to your site address (It's the people section of People and Groups), then select settings, list settings.

    New Site User Edit Screen

    This second screen is accessed by just clicking on the user's name or image in a security group or the All Users screen.

     After a 5 to 30 minutes time period (this seems to be about the same time period - and perhaps the same sptimer job? - as updates to your MySite "About Me" section, which appears in the user info screen), the security information is updated, and looks like the screen shots below. 

    Updated Site Security Columns 

    Notice that there are only two columns listed (above), and all the fields in the User Information (below) are now read-only.

      Updated User Edit Screen

    At the time when this change happens, the site will now appear on the My SharePoint Sites list.  My belief is that this conversion process changes the security table to a series of objects that are now readable by SharePoint's core system as security, rather than a list.  The My SharePoint Links object calls a security lookup that cannot read from those unconverted sites, only from converted ones. 

     

    When things break... 

    So what exactly was the problem we were seeing then?  Based on the above information, I found that the few sites we had that never populated on the My SharePoint Links list all still had that "new site" security list that had not yet been converted.  The sites had been created days ago, in a few cases over a month ago, but the sites never changed.

    This led me to alter my belief about this possible sptimer job.  The behavior makes me believe that there is a "convert flag" somewhere in the site information that tells SharePoint if it is a new site, or a converted site.  This (possibly fictional) sptimer job only converts sites where the flag has not yet been set, and it sets this flag after the conversion. 

     

    How to fix it when "things break"...

    Unfortunately, my call to MS Premiere ended up being a bit more of an educational session for them, and I still do not have a reasonable answer to this issue, although the issue is still open and they are researching this behavior now.  I did find that I could easily use my MOSS backup solution, AvePoint's DocAve, to backup content and restore it to a new site that had been converted, but this still leaves the question of how to fix a site without a 3rd party tool and a bunch of delete/recreate operations.  I'm still waiting for that answer, but now I think I understand how this part of SharePoint functions a bit better.  I'll post the answer (if there is one) whenever I get it...

     

  • MSCS Rolling upgrade to Windows 2003 SP2

    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.3790
    00000384.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.171
    00000384.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] Initialization
    00000384.00000ba4::2007/08/31-00:30:04.187 ERR  [DM] DmInitialize: The hive was loaded- rollback, unload and reload again
    00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] DmpRestartFlusher: Entry
    00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] DmpUnloadHive: unloading the hive
    00000384.00000ba4::2007/08/31-00:30:04.187 INFO [Qfs] QfsSetFileAttributes C:\WINDOWS\Cluster\CLUSDB.BKP$ 80, status 2
    00000384.00000ba4::2007/08/31-00:30:04.187 INFO [Qfs] QfsDeleteFile C:\WINDOWS\Cluster\CLUSDB.BKP$, status 2
    00000384.00000ba4::2007/08/31-00:30:04.187 INFO [DM] Loading cluster database from C:\WINDOWS\Cluster\CLUSDB
    00000384.00000ba4::2007/08/31-00:30:04.203 INFO [DM] DmpStartFlusher: Entry
    00000384.00000ba4::2007/08/31-00:30:04.203 INFO [DM] DmpStartFlusher: thread created
    00000384.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] Initializing
    00000384.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 running
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [CS] Service Domain Account = Domain\ServiceAccount
    00000384.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 mapper
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [INIT] Attempting to join cluster CLUSTERNETNAME
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.97.130.141
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.255.255.143
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.101.130.141
    00000384.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 CLUSTERNODE2
    00000384.00000ba4::2007/08/31-00:30:04.218 INFO [JOIN] Spawning thread to connect to sponsor 10.97.130.142
    00000384.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 CLUSTERNETNAME
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [API] Online read only
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Creating group 16f59b7a-3ddf-41cf-b2f4-dcc74134ef72
    00000384.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-3079612f4533
    00000384.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 Address
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found
    00000384.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-ae3c14e99762
    00000384.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 Name
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found
    00000384.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-3079612f4533
    00000384.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-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] 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 Disk
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: adding node 1 to resource type's possible node list
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] FmpAddPossibleNodeToList: Warning, node 2 not found
    00000384.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 monitor
    00000d28.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.00000001
    00000384.00000ba4::2007/08/31-00:30:37.218 INFO [FM] Resmon LRPC EP name is LRPC00000d28.00000001
    00000384.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 269b269b
    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} - 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 1313632
    00000384.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 1
    00000d28.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 attach
    00000d28.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 512
    00000d28.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 0
    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} - 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 = 5086
    00000384.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 5086
    00000384.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] EvShutdown
    00000384.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: Entry
    00000384.00000ba4::2007/08/31-00:31:14.343 INFO [FM] FmpCleanupGroups: Exit
    00000384.00000ba4::2007/08/31-00:31:14.343 INFO [Dm] DmShutdown
    00000384.00000ba4::2007/08/31-00:31:14.343 INFO [DM] DmpShutdownFlusher: Entry
    00000384.00000ba4::2007/08/31-00:31:14.343 INFO [DM] DmpShutdownFlusher: Setting event
    00000384.00000e24::2007/08/31-00:31:14.343 INFO [DM] DmpRegistryFlusher: got 0
    00000384.00000e24::2007/08/31-00:31:14.343 INFO [DM] DmpRegistryFlusher: exiting
    00000384.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 = 5086
    00000d28.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 = 00000000
    00000d28.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 9e1c3236
    00000d28.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.

     


Need SharePoint Training? Attend a SharePoint Bootcamp!

Posts (c) their respective authors. Everything else (c) 2007 SharePoint Experts