none
DPM 2010 system state and BMR backups failing for ConfigMgr Sp2 R2 running server 2008 R2 RRS feed

  • Question

  • I was able to add my configmgr server to a protection group and backup all sql dbs and the initial bmr and system state.  Since the first day after backing up the system state and bmr constantly show "replica is inconsistent".  I have tried running consistency checks many times and after several hours it will return to the same error.  The sql dbs have backed up fine without any issues the entire time.  There are no errors in either event log for the dpm server or the configmgr server.  I have ran vssadmin list writers and all writers show "no error" although many of them remain in the state: "waiting for completion".  I also installed hotfix kb981640 thinking this might fix the issue but the same results are occurring.  I have also tried removing system state and bmr from the PG and then readding them with no success.   
    NARS System Administrator
    Wednesday, January 26, 2011 4:23 PM

Answers

  • Well it appears the issue was having the sql databases on the C volume.  After moving all of the system and user dbs to the D volume Friday I was able to take the initial BMR/Sysstate backup in DPM.  The syncronization also worked this morning at 1 am automatically.  So I guess the moral of the story is, keep your SQL dbs off the C volume because you never know what will break if you don't :)

     


    NARS System Administrator
    • Marked as answer by zzackw1975 Monday, May 23, 2011 1:56 PM
    Monday, May 23, 2011 1:56 PM

All replies

  • I had the same issue and it was because of a VSS writer causing errors . First thing , try "VSSADMIN Writer list" on protected server and see if any writer has errors. I think DPM uses ASR writer for system state. Since this is a SQL server my guess is that one of the sql writers is cauing ASR to error out.

    In my case , it was Forefront writer that was causing an issue , I stopped it and re-start DPM agent service . then got VSSadmin and all writers were back to healthy state. a hot fix fixed the issue with Forefront writer later.

    Thursday, January 27, 2011 7:04 PM
  • I did the vssadmin list writers and it doesn't show any errors.  It says they are all stable and the ASR writer is one of the writers "waiting for completion" but it never completes.  After trying a resync in DPM, it keeps going back to replica is inconsistent for bmr and system state but the sql dbs are all "ok".  We tried removing the system state and bmr from the PG and readding it but still ended up with the same situation. 

    Has anyone had any issues backing up a configmgr 2007 sp2 r2 site db on server 2008 R2 using DPM 2010?  The sql version is 2005 9.00.4035. 


    NARS System Administrator
    Monday, January 31, 2011 7:10 PM
  • It keeps failing as long as you don't get ASR writer available. have you tried rebooting this machine ? have you tried stop all 3rd party writers ( e.g. SQL writers ) and get another vssadmin ? something is causing it to stay in that state.
    Tuesday, February 1, 2011 9:47 PM
  • I stopped the sms writer and the sql writer after rebooting the configmgr server but the ASR Writer is still waiting for completion.  The sys state and bmr backups are still synchronizing but I'm sure they will end up being inconsistent again. 

    Would it be a good idea to remove those backups from the protection group again and re-add them?  Are there any specific steps I should take when doing this or is there anything else I can try?

     

     


    NARS System Administrator
    Tuesday, February 8, 2011 5:22 PM
  • I'm still having the same issues even after re-adding system state and bmr to the protection group.  It completes the initial backup but the next day it gets stuck synchronizing for over 12 hours before it decides to error out.  Does anyone with SCCM and DPM 2010 experience have any suggestions?

     

     


    NARS System Administrator
    Wednesday, February 16, 2011 8:42 PM
  • Hello,

    I have DPM 2010 successfully backing up SCCM 2007 BMR  and have no issues to date.  

    I suggest the following:

    a.) Make sure the protected server drive has enough space (at least 30gig) to the BMR snapshot.
    b.) On the protected server check the backup logs. Windows 2008 backup logs are located in the %windir%\logs\WindowsServerBackup folder
    c.) If the protected server does NOT have enough space, you can alter the location that the backup is kept by following: http://technet.microsoft.com/en-us/library/bb809015.aspx .  Changing the PSDatasourceConfig.xml file location will accomplish this.
    d.) See if you can take a system state backup using wbadmin on the protected server. This is what DPM uses to take the system state\BMR backup, if this component does not work then DPM never comes into play. This can be done via the command: Wbadmin start systemstatebackup -backuptarget:c:
    e.) Check the target server event log for VSS errors.  Does this server have any related VSS or backup errors listed?

    Thanks
    Shane

    • Proposed as answer by ShaneB. _ Friday, April 1, 2011 12:09 PM
    • Unproposed as answer by zzackw1975 Friday, April 1, 2011 2:05 PM
    Tuesday, March 15, 2011 7:18 PM
  • a) i extended the c drive so that over 40gb were available for backups.  I changed the psdatasourceconfig.xml file to backup to the c volume (was pointed to d).

    b)backup logs aren't showing me any solutions to this issue.

    c)location is altered to c volume

    d) I was able to create a local systemstate backup using wbadmin and it completed successfully.  I was also able to add just system state protection for this server to DPM and it completed successfully.  After adding BMR and running a consistency check, I get an error that the vss copy backup failed, the device is not connected during the systemstate backup of c.  I have verified connectivity to DPM being logged into that server at the same time and there were no issues with it. 

    e) there haven't been any vss errors in the event logs at all nor backup errors. 

    So currently, we know a local systemstate backup works and a DPM system state backup works.  With the added BMR backup the consistency checks fail with the error listed in d.  There is still over 30gb of space available on c so it shouldn't be a disk storage issue. 

     


    NARS System Administrator
    Thursday, March 31, 2011 8:34 PM
  • BMR still isn't backing up.  After I add it to the protection group and run a consistency check, it hangs there.  In Windows Server Backup on the sccm server it shows a status of "Preparing media to store backups..." but just hangs on that point while backing up the system reserved (100mb) area of the drive. 


    NARS System Administrator
    Friday, April 1, 2011 6:01 PM
  • Hello,

    I suggest you start a BMR CC and then go to the target server. Open up two command prompts.

    VSS
    ***
    1.) While the BMR attempt is being done via DPM when it gets into this hung state from the first command prompt type:  

     "vssadmin list writers"  <------Do you note if the writers ever enter a failed or hung state?

    2.) On the second command prompt type:  "vssadmin list shadows" <---Do you notice any shadow copies being taken?


    Wbadmin
    ********
    If from a command prompt if you type:  "Wbadmin start systemstatebackup -backuptarget:c:" <------Does this complete at all.  This is the equivelant of a local BMR being taken.

    Thanks
    Shane

    Monday, April 4, 2011 9:16 PM
  • I went ahead and started a BMR and ran the commands you gave above and they did not show any errors and I did see shadow copies being taken.  This time the BMR completed successfully to DPM. 

    I also already ran a local systemstate backup and it worked fine. 

    So I guess let's give it 24 hours and see if the BMR is still stable in DPM.  I used the defaults when I added it to the protection group but I'm not sure how often DPM takes a BMR backup.  Last time I added both BMR and Systemstate to DPM and it looked fine the 1st day but after that it would become inconsistent and fail to complete a consistency check. 

    I will check back in tomorrow after I see if this backup remains stable or not.

     

     


    NARS System Administrator
    Tuesday, April 5, 2011 3:36 PM
  • When I checked the backups this morning DPM shows that system protection has been backing up for 11 hours but no data has been transferred to DPM.  I checked Windows Server Backup on the protected server and it is 25% complete for the local disk C, 10.74 gb of 42.00 GB.  It has been stuck at this point since I checked it. 

    I ran vssadmin list writers and none of them show errors but several of them are listed as "waiting for completion".  A vssadmin list shadows shows a shadow copy was started last night around 10pm which is when this backup usually occurs. 

    So, once again I don't know why these recovery points for the combination of system protection/BMR continue to time out.  There is still 32gb free on the C volume and the vhd backup file for system protection only uses 8.9 GB. 

    Shane, any other ideas?

    thanks

     


    NARS System Administrator
    Wednesday, April 6, 2011 2:19 PM
  • One additional point I noticed is that when I went to cancel the backup job in DPM it also stated that the 7 sql db recovery points would be cancelled as well because they are related to the system protection job.  Could this mean that the sql backups are causing the job to hang for some reason and how can I find out?

     

     


    NARS System Administrator
    Wednesday, April 6, 2011 4:44 PM
  • Hello,

    Try placing the BMR in it's own protection group.
    Does this fail as well?


    Shane
    Saturday, April 9, 2011 12:10 AM
  • I placed BMR and System Protection in a separate Protection Group that only contains this server currently.  When I ran the Consistency check, in Windows Server Backup on the Protected Server I could see that all of the data was transferred and it shows everything is complete but, it still shows Backup in Progress and it's been running for over 3 hours.  In DPM, it just shows that verification is still in progress.  There are no error logs or errors in the event logs for either server.  I don't think this backup should take this long especially since it shows that all of the steps are complete in the Backup on WSB.  Not sure why it decided to hang at this point so I'm going to cancel this backup and then try it again.

     

     

     

     


    NARS System Administrator
    Tuesday, April 12, 2011 5:42 PM
  • Same deal in its own protection group as in the other protection group, I was able to get a BMR/Sys state backup to complete but once it tried to do the 10pm recovery point it hung and would not complete.  I came in the next day and had to cancel it and reboot the protected server to get WSB to work again.  I haven't been able to even get another BMR to work since then (gets to about 5% complete on volume1 in WSB then hangs there forever).   
    NARS System Administrator
    Monday, April 18, 2011 2:22 PM
  • I've built and rebuilt a protection group just for bare metal backups but still haven't had any success in even creating the initial backup now.  I've rebooted the PS and the DPM server.  When I try to run a consistency check that includes both bmr and system state it invariably hangs.  The latest time it only reached 1% of the C: volume backup (looking in WSB on the PS).  The most annoying part of it is that I can't find any good logs or error reports to indicate what the problem is. 

     

     


    NARS System Administrator
    Wednesday, April 27, 2011 2:20 PM
  • Hello,

    The logs that may be of use would be the MSDPMCurr.errlog and the DPMAccessManager*.* log within the temp directory of DPM ( %Program Files%\Microsoft DPM\DPM\Temp)
    Try this, make sure you have enough space on the protected server and replica and recovery point volume for the BMR.  Perform a consistency check. Once it fails go to the logs and search for that failed instance.  Suggest you start from the bottom and search up for the server name.  There may be an indication as to what the problem is.  Please keep in mind that the logs are not always easy to read though.  If you want to paste a snippet on a reply to this forum then that's ok.

    What does the DPM alerts in event viewer state?


    Thanks
    Shane

    Thursday, April 28, 2011 1:19 PM
  • I've found several of the logs you mentioned and I am including a snippet from the most recent one, DPMRACurr.errlog (5/5/2011):

    1B60 1720 05/05 13:30:03.380 03 timer.cpp(503) [0000000000372E58]  ACTIVITY CTimerMgr::TimerThreadInternal
    1B60 1FA4 05/05 13:30:03.380 29 dpmra.cpp(162) [00000000003213C0]  NORMAL CDPMRA::Initialize [00000000003213C0]
    1B60 1FA4 05/05 13:30:03.380 31 vaagent.cpp(226)   NORMAL CVAAgent: Initialize globals
    1B60 1FA4 05/05 13:30:03.397 29 mta.cpp(126)   ACTIVITY CMTA::AddSchemasToSchemaCache => Initialize loaded schemas
    1B60 1FA4 05/05 13:30:03.418 29 dpmra.cpp(184) [00000000003213C0]  NORMAL CDPMRA::Initialize loaded schemas
    1B60 1FA4 05/05 13:30:03.418 22 genericthreadpool.cpp(75) [00000000002FFD80]  NORMAL CGenericThreadPool: constructor
    1B60 1FA4 05/05 13:30:03.418 22 genericthreadpool.cpp(804) [00000000002FFD80]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    1B60 1FA4 05/05 13:30:03.418 29 dpmra.cpp(271) [00000000003213C0]  NORMAL CreateDefaultSubTask [00000000003213C0]
    1B60 1FA4 05/05 13:30:03.419 29 dpmra.cpp(194) [00000000003213C0]  NORMAL Temporary storage path reg key found
    1B60 1FA4 05/05 13:30:03.419 29 dpmra.cpp(210) [00000000003213C0]  NORMAL MTA Temp location Path = [C:\Program Files\Microsoft Data Protection Manager\DPM\temp\MTA\]
    1B60 1FA4 05/05 13:30:03.421 29 mtamethrottlehelper.cpp(114) [0000000000398F90]  NORMAL Hr: = [0x80070002] Number of encryption threads = [2]
    1B60 1D18 05/05 13:30:03.421 29 mtamethrottlehelper.cpp(254) [0000000000398F90]  NORMAL CEncryptionThrottleHelper: Opened handle to resutils.dll succesfully
    1B60 1FA4 05/05 13:30:03.422 03 service.cpp(298) [000000000024FBD0]  ACTIVITY CService::AnnounceServiceStatus
    1B60 1A10 05/05 13:30:03.422 29 mtamethrottlehelper.cpp(254) [0000000000398F90]  NORMAL CEncryptionThrottleHelper: Opened handle to resutils.dll succesfully
    1B60 0F74 05/05 13:30:03.474 29 radefaultsubtask.cpp(308) [0000000000398B00] E0BA290D-217D-4325-933C-6C157E7A0DE0 ACTIVITY CMTADefaultSubTask::CommandReceivedSpecific => Command RefreshConnectivity Received
    1B60 0F74 05/05 13:30:03.474 05 genericstatus.cpp(1337) [0000000000399210] E0BA290D-217D-4325-933C-6C157E7A0DE0 NORMAL Windows Qfe KB no: [KB948465] is not applicable on this machine
    1B60 0F74 05/05 13:30:03.474 05 genericstatus.cpp(1337) [0000000000399210] E0BA290D-217D-4325-933C-6C157E7A0DE0 NORMAL Windows Qfe KB no: [KB971394] is not applicable on this machine
    1B60 0F74 05/05 13:30:07.406 05 genericstatus.cpp(1528) [0000000000399210] E0BA290D-217D-4325-933C-6C157E7A0DE0 NORMAL majorVerNum[3], minorVerNum[0], buildNum[7696], hotfixNum[0]
    1B60 1E1C 05/05 13:33:38.071 03 service.cpp(147) [000000000024FBD0]  ACTIVITY CService::ServiceHandlerExInternal
    1B60 1160 05/05 13:35:07.387 03 runtime.cpp(1652) [0000000000324780]  NORMAL CDLSRuntime::ProcessIdleTimeout
    1B60 1160 05/05 13:35:07.387 03 runtime.cpp(646) [0000000000324780]  NORMAL CDLSRuntime::Uninitialize, bForce: 0
    1B60 1160 05/05 13:35:07.387 05 genericagent.cpp(264) [00000000003213C0]  NORMAL Agent Can Shutdown if there is only default wokitem active[1]
    1B60 1160 05/05 13:35:07.387 29 dpmra.cpp(360) [00000000003213C0]  NORMAL CDPMRA::Shutting down dpmra, force-shutdown :yes
    1B60 1160 05/05 13:35:07.387 03 workitem.cpp(391)   NORMAL Timing out WI [000000000035A980], WI GUID = {B71B4544-7067-4A30-B5FB-BA320B10D82A}, ..last DM activity happened 17349578msec back, WI Idle Timeout = 390000msec
    1B60 1160 05/05 13:35:07.387 22 genericthreadpool.cpp(664) [00000000002FFD80]  NORMAL CGenericThreadPool: Waiting for threads to exit
    1B60 1CE0 05/05 13:35:09.389 20 cc_base.cpp(1226) [0000000000365B00]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1CE0 05/05 13:35:09.389 20 cc_base.cpp(1226) [00000000003627D0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1CE0 05/05 13:35:09.389 20 cc_base.cpp(1226) [0000000000360460]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1CE0 05/05 13:35:09.389 20 cc_base.cpp(1226) [000000000035E0F0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1968 05/05 13:35:09.389 20 cc_base.cpp(1226) [0000000000367DF0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1968 05/05 13:35:09.390 20 cc_base.cpp(1226) [00000000002F7FD0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1968 05/05 13:35:09.390 20 cc_base.cpp(1226) [000000000036E6C0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1968 05/05 13:35:09.390 20 cc_base.cpp(1226) [000000000036C3D0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1968 05/05 13:35:09.390 20 cc_base.cpp(1226) [000000000036A0E0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1CE0 05/05 13:35:09.391 20 cc_base.cpp(1226) [00000000003709B0]  NORMAL DM: Aborting  http state machine for reason 0
    1B60 1160 05/05 13:35:09.392 22 genericthreadpool.cpp(664) [0000000000324780]  NORMAL CGenericThreadPool: Waiting for threads to exit
    1B60 1720 05/05 13:35:11.393 03 timer.cpp(513) [0000000000372E58]  ACTIVITY Shutting down timer thread.
    1B60 1160 05/05 13:35:11.393 03 service.cpp(81)   ACTIVITY CService::StopThisService
    1B60 1160 05/05 13:35:11.393 03 service.cpp(281) [000000000024FBD0]  ACTIVITY CService::StopService()
    1B60 1FA4 05/05 13:35:11.393 03 service.cpp(298) [000000000024FBD0]  ACTIVITY CService::AnnounceServiceStatus
    0B08 0F1C 05/05 13:57:31.414 03 runtime.cpp(818) [0000000000334780]  ACTIVITY InitializeSecurity found 3 authorized entities
    0B08 0F1C 05/05 13:57:31.414 03 runtime.cpp(836) [0000000000334780]  ACTIVITY InitializeSecurity added COM perm for corp.narsnet.com\COLO-BAK-01
    0B08 0F1C 05/05 13:57:31.415 03 runtime.cpp(854) [0000000000334780]  ACTIVITY InitializeSecurity added COM perm for DPMRADCOMTrustedMachines
    0B08 0F1C 05/05 13:57:31.415 03 runtime.cpp(891) [0000000000334780]  ACTIVITY InitializeSecurity added DM perm for DPMRADmTrustedMachines
    0B08 0F1C 05/05 13:57:31.416 03 runtime.cpp(94)   NORMAL Found 1 writer account(s) under VSS access control.
    0B08 0F1C 05/05 13:57:31.416 03 runtime.cpp(161)   NORMAL Added writer account [0] 'NT Authority\NetworkService' to the DACL.
    0B08 0F1C 05/05 13:57:31.424 22 genericthreadpool.cpp(804) [0000000000334780]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[20]
    0B08 0F1C 05/05 13:57:31.424 22 agentutils.cpp(2624)   WARNING Failed: Hr: = [0x80070645] : U: lVal : hr
    0B08 1008 05/05 13:57:31.424 03 timer.cpp(490)   ACTIVITY CTimerMgr::TimerThread
    0B08 1008 05/05 13:57:31.424 03 timer.cpp(503) [00000000003673C0]  ACTIVITY CTimerMgr::TimerThreadInternal
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.431 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.433 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.433 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.433 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.433 20 cc_base.cpp(761) [000000000036E0F0]  NORMAL DM: - EndPoint:000000000036DF50, Family: 2, Indx:5, Port:0
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(761) [0000000000370460]  NORMAL DM: - EndPoint:000000000036DF50, Family: 2, Indx:5, Port:0
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(761) [00000000003727D0]  NORMAL DM: - EndPoint:000000000036DF50, Family: 2, Indx:5, Port:0
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(761) [0000000000375B00]  NORMAL DM: - EndPoint:000000000036DF50, Family: 2, Indx:5, Port:0
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 2, QoS Index: 5
    0B08 0F1C 05/05 13:57:31.434 20 cc_base.cpp(761) [0000000000377DF0]  NORMAL DM: - EndPoint:000000000036DF50, Family: 2, Indx:5, Port:0
    0B08 0F1C 05/05 13:57:31.435 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.435 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.435 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(761) [000000000037A0E0]  NORMAL DM: - EndPoint:000000000036E020, Family: 23, Indx:4, Port:0
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(761) [000000000037C3D0]  NORMAL DM: - EndPoint:000000000036E020, Family: 23, Indx:4, Port:0
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(761) [000000000037E6C0]  NORMAL DM: - EndPoint:000000000036E020, Family: 23, Indx:4, Port:0
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.436 20 cc_base.cpp(761) [00000000003809B0]  NORMAL DM: - EndPoint:000000000036E020, Family: 23, Indx:4, Port:0
    0B08 0F1C 05/05 13:57:31.437 20 cc_base.cpp(913)   NORMAL DM: - Spotted QoS IPv6, Index:4
    0B08 0F1C 05/05 13:57:31.437 20 cc_base.cpp(908)   NORMAL DM: - Spotted QoS IPv4, Index:5
    0B08 0F1C 05/05 13:57:31.437 20 cc_base.cpp(1036)   NORMAL Created Socket with Family: 23, QoS Index: 4
    0B08 0F1C 05/05 13:57:31.437 20 cc_base.cpp(761) [00000000004C7FD0]  NORMAL DM: - EndPoint:000000000036E020, Family: 23, Indx:4, Port:0
    0B08 0F1C 05/05 13:57:31.437 20 commengine.cpp(350) [00000000003671E0]  ACTIVITY Hr: = [0x80070002] ConnectionNoActivityTimeout: 300
    0B08 0F1C 05/05 13:57:31.437 20 commengine.cpp(364) [00000000003671E0]  ACTIVITY Hr: = [0x80070002] m_dwConnectionNoActivityTimeoutForSlowReceiver: 3600
    0B08 107C 05/05 13:57:31.446 03 timer.cpp(490)   ACTIVITY CTimerMgr::TimerThread
    0B08 107C 05/05 13:57:31.446 03 timer.cpp(503) [0000000000382E58]  ACTIVITY CTimerMgr::TimerThreadInternal
    0B08 0F1C 05/05 13:57:31.447 29 dpmra.cpp(162) [00000000003313C0]  NORMAL CDPMRA::Initialize [00000000003313C0]
    0B08 0F1C 05/05 13:57:31.447 31 vaagent.cpp(226)   NORMAL CVAAgent: Initialize globals
    0B08 0F1C 05/05 13:57:31.464 29 mta.cpp(126)   ACTIVITY CMTA::AddSchemasToSchemaCache => Initialize loaded schemas
    0B08 0F1C 05/05 13:57:31.487 29 dpmra.cpp(184) [00000000003313C0]  NORMAL CDPMRA::Initialize loaded schemas
    0B08 0F1C 05/05 13:57:31.487 22 genericthreadpool.cpp(75) [00000000004CFD80]  NORMAL CGenericThreadPool: constructor
    0B08 0F1C 05/05 13:57:31.487 22 genericthreadpool.cpp(804) [00000000004CFD80]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    0B08 0F1C 05/05 13:57:31.487 29 dpmra.cpp(271) [00000000003313C0]  NORMAL CreateDefaultSubTask [00000000003313C0]
    0B08 0F1C 05/05 13:57:31.487 29 dpmra.cpp(194) [00000000003313C0]  NORMAL Temporary storage path reg key found
    0B08 0F1C 05/05 13:57:31.487 29 dpmra.cpp(210) [00000000003313C0]  NORMAL MTA Temp location Path = [C:\Program Files\Microsoft Data Protection Manager\DPM\temp\MTA\]
    0B08 0F1C 05/05 13:57:31.489 29 mtamethrottlehelper.cpp(114) [00000000003A8F90]  NORMAL Hr: = [0x80070002] Number of encryption threads = [2]
    0B08 1BDC 05/05 13:57:31.489 29 mtamethrottlehelper.cpp(254) [00000000003A8F90]  NORMAL CEncryptionThrottleHelper: Opened handle to resutils.dll succesfully
    0B08 0F1C 05/05 13:57:31.489 03 service.cpp(298) [00000000000EFC20]  ACTIVITY CService::AnnounceServiceStatus
    0B08 1C6C 05/05 13:57:31.489 29 mtamethrottlehelper.cpp(254) [00000000003A8F90]  NORMAL CEncryptionThrottleHelper: Opened handle to resutils.dll succesfully
    0B08 1B78 05/05 13:57:31.535 29 radefaultsubtask.cpp(337) [00000000003A8B00] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 ACTIVITY CRADefaultSubTask::CommandReceivedSpecific => Command SetActiveOwner Received
    0B08 1B78 05/05 13:57:31.710 03 workitem.cpp(86) [00000000003A9280] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 ACTIVITY Idle Timer created with timeout = 390000
    0B08 1B78 05/05 13:57:31.906 31 vadatasourcestate.cpp(729)  62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 WARNING Failed: Hr: = [0x8007007e] GetModuleHandle failed for Library [GenericNonVssDatasourceHelperPlugin], will try LoadLibrary
    0B08 1B78 05/05 13:57:32.654 18 agentutils.hpp(68)  62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 WARNING Failed: Hr: = [0x80070002] : F: lVal : r.GetValue(pszKey, pT)
    0B08 1B78 05/05 13:57:32.654 18 fsutils.cpp(4426)  62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CClientReadThrottler::InitializeWaitForClientRead Failed to read sleep time from registry [hr = 0x80070002]. Setting default [50 ms].
    0B08 1B78 05/05 13:57:32.662 31 dllmain.cpp(36)  62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL GenericNonVssDatasourceHelperPlugin: DLL_PROCESS_ATTACH
    0B08 1730 05/05 13:57:32.677 31 vssbaserequestor.cpp(62) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssBaseRequestor: constructor [00000000003ABA40]
    0B08 1730 05/05 13:57:32.677 31 vsssnapshotrequestor.cpp(76) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [00000000003ABA40]
    0B08 1730 05/05 13:57:32.677 31 vssbaserequestor.cpp(99) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssBaseRequestor::Initialize [00000000003ABA40]
    0B08 1730 05/05 13:57:32.677 31 vsssnapshotrequestor.cpp(170) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssSnapshotRequestor::InitializeSnapshotCreation [00000000003ABA40]
    0B08 1730 05/05 13:57:32.685 22 agentutils.cpp(2373)  62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 WARNING Failed: Hr: = [0x80070002] Could not open HKEY_LOCAL_MACHINE\Software\Microsoft\Microsoft Data Protection Manager\Agent\2.0
    0B08 1730 05/05 13:57:32.878 31 vsssnapshotrequestor.cpp(94) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [00000000003ABA40]
    0B08 1730 05/05 13:57:32.878 31 vsssnapshotrequestor.cpp(1763) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssSnapshotRequestor::CleanUp [00000000003ABA40]
    0B08 1730 05/05 13:57:32.880 31 vssbaserequestor.cpp(80) [00000000003ABA40] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 NORMAL CVssBaseRequestor: destructor [00000000003ABA40]
    0B08 1730 05/05 13:57:32.880 03 workitem.cpp(272) [00000000003A9210] 62914F02-12D9-4D5E-ABD8-A02CF65EB9C5 ACTIVITY WorkItem stopping
    0B08 1730 05/05 13:57:33.198 29 radefaultsubtask.cpp(337) [00000000003A8B00] C0EE88D2-1A63-476F-B580-602FA12A5305 ACTIVITY CRADefaultSubTask::CommandReceivedSpecific => Command SetActiveOwner Received
    0B08 1730 05/05 13:57:33.378 03 workitem.cpp(86) [00000000003A9260] C0EE88D2-1A63-476F-B580-602FA12A5305 ACTIVITY Idle Timer created with timeout = 390000
    0B08 1730 05/05 13:57:33.971 31 aaxmlprocessingutils.cpp(49)  C0EE88D2-1A63-476F-B580-602FA12A5305 WARNING Failed: Hr: = [0x80070057] : F: lVal : E_INVALIDARG
    0B08 1730 05/05 13:57:34.060 31 basewriterhelperplugin.cpp(155) [00000000003B0FF0] C0EE88D2-1A63-476F-B580-602FA12A5305 NORMAL SetOperationType(1)
    0B08 1730 05/05 13:57:34.061 31 createsnapshotsubtask.cpp(977) [00000000003AEBF0] C0EE88D2-1A63-476F-B580-602FA12A5305 NORMAL Executing PreSnap step ""C:\Program Files\Microsoft Data Protection Manager\DPM\bin\BMRBackup.cmd"  \\COLO-BAK-01.corp.narsnet.com\39d39dbc8af7422ba5395034c6ffc7bf"
    0B08 096C 05/05 13:58:58.028 03 service.cpp(147) [00000000000EFC20]  ACTIVITY CService::ServiceHandlerExInternal
    0B08 096C 05/05 13:59:01.116 03 service.cpp(147) [00000000000EFC20]  ACTIVITY CService::ServiceHandlerExInternal
    0B08 1730 05/05 14:00:08.099 29 radefaultsubtask.cpp(308) [00000000003A8B00] A25F0497-4731-4064-9610-935913377A1F ACTIVITY CMTADefaultSubTask::CommandReceivedSpecific => Command RefreshConnectivity Received

    I checked this log while the BMR/Sys backup was frozen at 38% completion (didn't even make it past the system reserved area (33mb) this time).  I also ran vssadmin list shadows and the shadow backup did complete successfully.  Vssadmin list writers shows several writers "waiting for completion" but no errors.  I've also checked the system and application logs but there are no errors to speak of.  The backups just seem to hang at random and never unhang. 

     

     

     

     


    NARS System Administrator
    Thursday, May 5, 2011 2:13 PM
  • Hello,

    I was more interested in the MSDPMCurr.errlog and the DPMAccessManager*.* log.

    Thanks,
    Shane
    Friday, May 6, 2011 12:38 PM
  • These logs are so huge I don't know which parts to paste here hehe.  I can provide you the entire log if you want to email me (zackw@narsnet.com) an sftp site to upload them to.  These are the logs that were created this morning after I tried another BMR/sysstate backup on the sccm server.  The backup job finished creating shadow copies and then hangs at 0% completion of volume 1.  I had already rebooted the sccm server just so WSB would work. 

     

    From DPMAccessManagerCurr.errlog (5/6/2011):

    1088 1A20 05/06 09:02:55.822 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 09:02:55.823 09 engineservicesproxy.cpp(36)   NORMAL EngineServicesProxy::GetDbConnectionString()
    1088 1A20 05/06 09:02:55.824 62 AutoRerun.cs(56)   NORMAL Received alert not present in cache; AlertId=[33de733a-ef0b-4452-9800-956efd052c04], AlertType=[SynchronizationFailedAlert], Resolution=[InvisibleAndActive], CorrectiveAction=[AutoRerun], JobId=[4a7df077-02ba-4707-8db5-4f38554c3526], TaskDefId=[d8ebb66c-c8ca-4a87-b0e8-e5f65948f2c7]
    1088 1A20 05/06 09:02:55.828 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 09:02:55.828 15 schedulerservicesproxy.cpp(354)   NORMAL SchedulerServicesProxy::GetRunTimesForSingleJobDefinition. jobDefID=bb6d039c-2290-4700-b23d-283614f16b57, startDate=05/06/2011 04:02:55, endDate=05/06/2011 09:02:54, maxRunTimes=4096
    1088 1A20 05/06 09:02:55.836 62 AutoCorrectiveAction.cs(696)   NORMAL AutoHeal: Number of scheduled jobs found between 5/6/2011 4:02:55 AM and 5/6/2011 9:02:54 AM is 2 jobDefId bb6d039c-2290-4700-b23d-283614f16b57
    1088 1A20 05/06 09:02:55.836 62 AutoRerun.cs(94)   NORMAL AutoHeal: There is a scheduled job up for execution shortly.Skipping action; AlertId=[33de733a-ef0b-4452-9800-956efd052c04], JobdefId=[bb6d039c-2290-4700-b23d-283614f16b57]
    1088 1A20 05/06 09:02:55.836 62 AutoHeal.cs(180)   NORMAL Changing visibility of alert (AlertId=[33de733a-ef0b-4452-9800-956efd052c04], AlertType=[SynchronizationFailedAlert]) from [InvisibleAndActive] to [VisibleAndActive] Reason=[ValidateAction returned false]
    1088 1A20 05/06 09:02:55.836 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 09:02:55.836 09 engineservicesproxy.cpp(444)   NORMAL EngineServicesProxy::UpdateAlertVisibility(). alertId=33de733a-ef0b-4452-9800-956efd052c04, newVisibility=0, invisibilityTimeout=0
    1088 1A20 05/06 09:02:56.864 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 09:02:56.865 09 engineservicesproxy.cpp(36)   NORMAL EngineServicesProxy::GetDbConnectionString()
    1088 1A20 05/06 09:02:56.865 62 AutoRerun.cs(56)   NORMAL Received alert not present in cache; AlertId=[33de733a-ef0b-4452-9800-956efd052c04], AlertType=[SynchronizationFailedAlert], Resolution=[VisibleAndActive], CorrectiveAction=[AutoRerun], JobId=[00000000-0000-0000-0000-000000000000], TaskDefId=[d8ebb66c-c8ca-4a87-b0e8-e5f65948f2c7]
    1088 1A20 05/06 09:02:56.865 62 AutoRerun.cs(62)   NORMAL AutoHeal: JobId is empty or dpmServer is null; JobId=[00000000-0000-0000-0000-000000000000], AlertId=[33de733a-ef0b-4452-9800-956efd052c04], IsDpmServerNull=[False]
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Attempt 1 failed with exception Microsoft.Internal.EnterpriseStorage.Dls.DB.NonFatalDbException: exception ---> System.Data.SqlClient.SqlException: Transaction (Process ID 53) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.HasMoreRows()
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.ReadInternal(Boolean setTimeout)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at Microsoft.Internal.EnterpriseStorage.Dls.DB.SqlRetryReader.Read()
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    --- End of inner exception stack trace ---
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING *** Mojito error was: DatabaseNonFatalError; 0; None
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING --- SqlException details -----------------
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING System.Data.SqlClient.SqlException: Transaction (Process ID 53) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.HasMoreRows()
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.ReadInternal(Boolean setTimeout)
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING    at Microsoft.Internal.EnterpriseStorage.Dls.DB.SqlRetryReader.Read()
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING  Error = 1205
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Index #0
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Source: .Net SqlClient Data Provider
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Number: 1205
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING State: 51
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Class: 13
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Server: COLO-BAK-01\MSDPM2010
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Message: Transaction (Process ID 53) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Procedure: prc_AM_GetAllServersWithAgentsInstalled
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING Line: 13
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING --- Caller StackTrace -----------------
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:Read(); lineNo:0; ilOffset:2.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:ReadServersWithAgentsInstalled(); lineNo:0; ilOffset:70.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:ReadProductionServers(); lineNo:0; ilOffset:14.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:RefreshProductionServers(); lineNo:0; ilOffset:68.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:ProductionServerEventHandler(); lineNo:0; ilOffset:81.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:PollingThreadProc(); lineNo:0; ilOffset:183.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:Run(); lineNo:0; ilOffset:95.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING FileName:; Method:ThreadStart(); lineNo:0; ilOffset:32.
    1088 248C 05/06 10:30:04.103 09 Catalog.cs(486)   WARNING .
    1088 1A20 05/06 11:01:14.767 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 11:01:14.768 09 engineservicesproxy.cpp(36)   NORMAL EngineServicesProxy::GetDbConnectionString()
    1088 1A20 05/06 11:01:14.769 62 AutoHeal.cs(468)   NORMAL AutoHeal: IsAlertAutoHealable: AlertId=[33de733a-ef0b-4452-9800-956efd052c04], AlertType=[SynchronizationFailedAlert], IsAlertDeleted=[False], alertResolution=[Fixed]
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Attempt 1 failed with exception Microsoft.Internal.EnterpriseStorage.Dls.DB.NonFatalDbException: exception ---> System.Data.SqlClient.SqlException: Transaction (Process ID 54) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.HasMoreRows()
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.ReadInternal(Boolean setTimeout)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at Microsoft.Internal.EnterpriseStorage.Dls.DB.SqlRetryReader.Read()
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    --- End of inner exception stack trace ---
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING *** Mojito error was: DatabaseNonFatalError; 0; None
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING --- SqlException details -----------------
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING System.Data.SqlClient.SqlException: Transaction (Process ID 54) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.HasMoreRows()
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at System.Data.SqlClient.SqlDataReader.ReadInternal(Boolean setTimeout)
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING    at Microsoft.Internal.EnterpriseStorage.Dls.DB.SqlRetryReader.Read()
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING  Error = 1205
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Index #0
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Source: .Net SqlClient Data Provider
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Number: 1205
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING State: 51
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Class: 13
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Server: COLO-BAK-01\MSDPM2010
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Message: Transaction (Process ID 54) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Procedure: prc_AM_GetAllServersWithAgentsInstalled
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING Line: 13
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING --- Caller StackTrace -----------------
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:Read(); lineNo:0; ilOffset:2.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:ReadServersWithAgentsInstalled(); lineNo:0; ilOffset:70.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:ReadProductionServers(); lineNo:0; ilOffset:14.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:RefreshProductionServers(); lineNo:0; ilOffset:68.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:ProductionServerEventHandler(); lineNo:0; ilOffset:81.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:PollingThreadProc(); lineNo:0; ilOffset:183.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:Run(); lineNo:0; ilOffset:95.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING FileName:; Method:ThreadStart(); lineNo:0; ilOffset:32.
    1088 248C 05/06 12:30:06.685 09 Catalog.cs(486)   WARNING .
    1088 1A20 05/06 13:17:42.877 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 13:17:42.878 09 engineservicesproxy.cpp(36)   NORMAL EngineServicesProxy::GetDbConnectionString()
    1088 1A20 05/06 13:17:42.879 62 AutoHeal.cs(180)   NORMAL Changing visibility of alert (AlertId=[29d6a764-439c-440f-9505-1ce436ec20df], AlertType=[EvalShareInquiryAlert]) from [InvisibleAndActive] to [VisibleAndActive] Reason=[No AutoCorrectiveAction found]
    1088 1A20 05/06 13:17:42.879 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 13:17:42.879 09 engineservicesproxy.cpp(444)   NORMAL EngineServicesProxy::UpdateAlertVisibility(). alertId=29d6a764-439c-440f-9505-1ce436ec20df, newVisibility=0, invisibilityTimeout=0
    1088 1A20 05/06 13:17:43.903 09 proxyutils.cpp(73)   NORMAL CoreServicesProxy::CreateCoreServices(colo-bak-01.corp.narsnet.com)
    1088 1A20 05/06 13:17:43.903 09 engineservicesproxy.cpp(36)   NORMAL EngineServicesProxy::GetDbConnectionString()
    1088 248C 05/06 14:00:14.500 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 1b93706e-6a83-494c-98d2-fd810539263d
    1088 248C 05/06 14:00:14.500 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = c3f6ff2f-d0c1-40a7-bbc2-f5caa9ea0670
    1088 248C 05/06 14:00:14.501 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 4b157d03-39ea-48c9-99fe-f2b03ac7c2f2
    1088 248C 05/06 14:00:14.501 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = e533740b-e623-4422-9959-efa3c35bbfbd
    1088 248C 05/06 14:00:14.501 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 5535b9c0-0ca8-47d3-bcf0-ea99c3a66f3b
    1088 248C 05/06 14:00:14.501 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 3691ed1e-d18a-4a53-82a4-e9994638c21f
    1088 248C 05/06 14:00:14.502 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 2fa08d69-8410-4f12-a367-dde347190272
    1088 248C 05/06 14:00:14.502 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = 05dc66d0-af28-4679-bca6-cf4351a0f254
    1088 248C 05/06 14:00:14.502 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock = 18446744073709551612 MediaId = da8426f6-1d69-45ca-9767-c7b09bb2b64b
    1088 248C 05/06 14:00:14.503 45 ArchiveMedia.cs(1049)   NORMAL DataWrittenDisplayString: physicalBlockSize = 65536 highestBlockOffset = 18446744073709551612 firstFreeBlock =

    From MSDPMCurr.errlog (5/6/2011):

    16E0 1A54 05/06 14:16:55.343 02 EventManager.cs(88)   NORMAL Publishing event from TaskExecutor.cs(107): TaskCreated, [TaskID=da83d018-1264-450f-8deb-c25df7269344]
    16E0 1A54 05/06 14:16:55.362 01 TaskExecutor.cs(127)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL GenerateWorkplan(job=4a337132-0c41-41bb-892d-8e87e72f77df) - Finished (error=False), executing GenerateWorkplanCallback
    16E0 1A54 05/06 14:16:55.362 16 Task.cs(235)   NORMAL  Changing task state from 'Start' -> 'GenerateWorkplan' (da83d018-1264-450f-8deb-c25df7269344)
    16E0 1A54 05/06 14:16:55.364 16 ActiveJob.cs(1024)   NORMAL  Changing state of job: '4a337132-0c41-41bb-892d-8e87e72f77df' from 'GenerateWorkplan' -> 'Execute'
    16E0 1A54 05/06 14:16:55.365 02 EventManager.cs(88)   NORMAL Publishing event from ActiveJob.cs(1043): JobStateChange, [JobID=4a337132-0c41-41bb-892d-8e87e72f77df]
    16E0 1A54 05/06 14:16:55.371 16 ActiveJob.cs(774)   NORMAL  Begin new execution batch at task:(True)-26bb6787-8853-4684-8014-4528306d2537
    16E0 1A54 05/06 14:16:55.372 16 ActiveJob.cs(794)   NORMAL  Dispatching task for execution:True-26bb6787-8853-4684-8014-4528306d2537
    16E0 26E8 05/06 14:16:55.372 16 ActiveJob.cs(524)   NORMAL  Begin ExecuteTask:JobID=4a337132-0c41-41bb-892d-8e87e72f77df, ItemID=26bb6787-8853-4684-8014-4528306d2537
    16E0 26E8 05/06 14:16:55.373 01 TaskExecutor.cs(692)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Setting up Fsm: verb[85d11aaa-bbbc-427d-9932-eeb3fd4759f5]
    16E0 26E8 05/06 14:16:55.378 01 TaskExecutor.cs(489)  26BB6787-8853-4684-8014-4528306D2537 NORMAL ExecuteTask(job=4a337132-0c41-41bb-892d-8e87e72f77df) - Starting task instance
    16E0 0648 05/06 14:16:55.378 03 timer.cpp(490)   ACTIVITY CTimerMgr::TimerThread
    16E0 0648 05/06 14:16:55.378 03 timer.cpp(503) [000000003C3B1B78]  ACTIVITY CTimerMgr::TimerThreadInternal
    16E0 1A54 05/06 14:16:55.379 02 EventManager.cs(88)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Publishing event from TaskInstance.cs(407): TaskStart, [TaskID=26bb6787-8853-4684-8014-4528306d2537]
    16E0 1A54 05/06 14:16:55.405 01 TaskInstance.cs(444)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Task: Initial transition enqueued, startState='ConfigureProtection.StartState'
    16E0 1A54 05/06 14:16:55.416 27 FindActiveNodeBlock.cs(884)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Found Principal server for DatasourceId = 39d39dbc-8af7-422b-a539-5034c6ffc7bf Server= colo-cfm-01.corp.narsnet.com
    16E0 0648 05/06 14:17:03.469 03 timer.cpp(513) [000000003C3B1B78]  ACTIVITY Shutting down timer thread.
    16E0 26E8 05/06 14:17:03.469 02 EventManager.cs(88)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Publishing event from TaskInstance.cs(825): TaskStop, [TaskID=26bb6787-8853-4684-8014-4528306d2537]
    16E0 26E8 05/06 14:17:03.473 01 TaskExecutor.cs(849)  26BB6787-8853-4684-8014-4528306D2537 NORMAL Task stopped (state=Completed, error=Success; 0; None)
    16E0 26E8 05/06 14:17:03.473 16 Task.cs(235)   NORMAL  Changing task state from 'GenerateWorkplan' -> 'Execute' (26bb6787-8853-4684-8014-4528306d2537)
    16E0 26E8 05/06 14:17:03.474 16 ActiveJob.cs(774)   NORMAL  Begin new execution batch at task:(True)-da83d018-1264-450f-8deb-c25df7269344
    16E0 26E8 05/06 14:17:03.474 16 ActiveJob.cs(794)   NORMAL  Dispatching task for execution:True-da83d018-1264-450f-8deb-c25df7269344
    16E0 2650 05/06 14:17:03.475 16 ActiveJob.cs(524)   NORMAL  Begin ExecuteTask:JobID=4a337132-0c41-41bb-892d-8e87e72f77df, ItemID=da83d018-1264-450f-8deb-c25df7269344
    16E0 2650 05/06 14:17:03.478 01 DPMTaskController.cs(70)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL (job=4a337132-0c41-41bb-892d-8e87e72f77df, taskId=da83d018-1264-450f-8deb-c25df7269344) DPMTaskControllerHelper : ExecuteTask - CheckTaskStatus returned ReadyToExecute
    16E0 2650 05/06 14:17:03.478 01 TaskExecutor.cs(692)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Setting up Fsm: verb[c4cae2f7-f068-4a37-914e-9f02991868da]
    16E0 2650 05/06 14:17:03.480 27 CommonLoop.cs(343)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL DatamovePollingCmdTimeoutInMin = 30
    16E0 2650 05/06 14:17:03.483 01 TaskExecutor.cs(489)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL ExecuteTask(job=4a337132-0c41-41bb-892d-8e87e72f77df) - Starting task instance
    16E0 0F9C 05/06 14:17:03.483 03 timer.cpp(490)   ACTIVITY CTimerMgr::TimerThread
    16E0 0F9C 05/06 14:17:03.483 03 timer.cpp(503) [000000003781BC08]  ACTIVITY CTimerMgr::TimerThreadInternal
    16E0 0450 05/06 14:17:03.484 02 EventManager.cs(88)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Publishing event from TaskInstance.cs(407): TaskStart, [TaskID=da83d018-1264-450f-8deb-c25df7269344]
    16E0 0450 05/06 14:17:03.504 01 TaskInstance.cs(444)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Task: Initial transition enqueued, startState='Backup.StartState'
    16E0 1964 05/06 14:17:03.504 27 BackupMachine.cs(1897)  DA83D018-1264-450F-8DEB-C25DF7269344 ACTIVITY BackupMachine : Starting machine execution
    16E0 1608 05/06 14:17:03.505 27 DecideConsistencyCheckNeededBlock.cs(292)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Consistency Check (Needed) for datasource=39d39dbc-8af7-422b-a539-5034c6ffc7bf
    16E0 2650 05/06 14:17:03.510 27 FindActiveNodeBlock.cs(884)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Found Principal server for DatasourceId = 39d39dbc-8af7-422b-a539-5034c6ffc7bf Server= colo-cfm-01.corp.narsnet.com
    16E0 2650 05/06 14:17:03.513 27 OperationTypeLock.cs(766)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL In LockServer() of ReplicationOperationTypeLock, returning lockStatus = AcquiredLock
    16E0 2650 05/06 14:17:03.514 02 EventManager.cs(88)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Publishing event from Replica.cs(1916): ReplicaStatusChange, [DataSourceID=84382a72-61c2-49f1-b365-1424a0cbafa0]
    16E0 2650 05/06 14:17:03.518 27 OperationTypeLock.cs(671)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL In Lock() of ReplicationOperationTypeLock, returning lockStatus = AcquiredLock
    16E0 2430 05/06 14:17:03.522 02 EventManager.cs(88)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Publishing event from ServerAlert.cs(650): AlertStateChange, [ObjectId=39d39dbc-8af7-422b-a539-5034c6ffc7bf]
    16E0 2430 05/06 14:17:03.525 23 AlertVisibility.cs(263)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL StopAutoHealActionTimer: Timer for alertId=[6193b5d4-2489-423d-a3a8-12ca0e5b470c] not found
    16E0 2430 05/06 14:17:03.536 02 EventManager.cs(88)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Publishing event from ServerAlert.cs(556): AlertStateChange, [ObjectId=39d39dbc-8af7-422b-a539-5034c6ffc7bf]
    16E0 2430 05/06 14:17:03.542 27 BackupMachine.cs(2247)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL RaiseReplicaVerificationInProgressAlert = True for ReplicaId = 84382a72-61c2-49f1-b365-1424a0cbafa0
    16E0 20F0 05/06 14:17:03.638 09 ApplicationSettings_expanded.cs(912)   NORMAL Ignoring exception in ReadRegistryKey System.IO.IOException: The specified registry key does not exist.
    16E0 20F0 05/06 14:17:03.638 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Win32.RegistryKey.Win32Error(Int32 errorCode, String str)
    16E0 20F0 05/06 14:17:03.638 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Win32.RegistryKey.GetValueKind(String name)
    16E0 20F0 05/06 14:17:03.638 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Internal.EnterpriseStorage.Dls.Utils.ApplicationSettings.ReadRegistryKey(String registryKeyPath, String registryKeyName, Int32 registryValueKind)
    16E0 20F0 05/06 14:17:03.648 09 ApplicationSettings_expanded.cs(912)   NORMAL Ignoring exception in ReadRegistryKey System.IO.IOException: The specified registry key does not exist.
    16E0 20F0 05/06 14:17:03.648 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Win32.RegistryKey.Win32Error(Int32 errorCode, String str)
    16E0 20F0 05/06 14:17:03.648 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Win32.RegistryKey.GetValueKind(String name)
    16E0 20F0 05/06 14:17:03.648 09 ApplicationSettings_expanded.cs(912)   NORMAL    at Microsoft.Internal.EnterpriseStorage.Dls.Utils.ApplicationSettings.ReadRegistryKey(String registryKeyPath, String registryKeyName, Int32 registryValueKind)
    16E0 0450 05/06 14:17:04.419 27 DeleteBitmapsBlock.cs(202)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL No bitmap deleted physically, deleting bitmaps from Database for datasource=39d39dbc-8af7-422b-a539-5034c6ffc7bf
    16E0 2108 05/06 14:17:04.426 18 fsutils.cpp(3710)   WARNING Failed: Hr: = [0x80070002] : CreateFile failed for \\?\Volume{448ae4c3-299a-11e0-9001-001018748854}\39d39dbc-8af7-422b-a539-5034c6ffc7bf\DatasourceVolumeMapping.xml
    16E0 1C1C 05/06 14:17:04.427 18 fsutils.cpp(3710)   WARNING Failed: Hr: = [0x80070002] : CreateFile failed for \\?\Volume{448ae4c3-299a-11e0-9001-001018748854}\39d39dbc-8af7-422b-a539-5034c6ffc7bf\Incremental\
    16E0 20F0 05/06 14:17:04.481 09 coreservices.cpp(7011)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CCoreServices::UpdateAlertVisibilityIfInvisible() entered
    16E0 20F0 05/06 14:17:04.481 16 engineservices.cpp(356)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CEngineServices::UpdateAlertVisibilityIfInvisible entered. alertId={2EAC5467-3E1F-4BAE-B891-A1D63CAD7521}, newVisibility=0, invisibilityTimeout=0
    16E0 20F0 05/06 14:17:04.484 02 EventManager.cs(88)   NORMAL Publishing event from ServerAlert.cs(722): AlertStateChange, [ObjectId=39d39dbc-8af7-422b-a539-5034c6ffc7bf]
    16E0 2430 05/06 14:17:04.599 02 EventManager.cs(88)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL Publishing event from RecoverySourceFactory.cs(230): DatasetStateChange, [DatasetID=3b115f1a-9a47-478b-a84b-818c2c047435]
    16E0 20F0 05/06 14:17:09.723 09 coreservices.cpp(5453)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CCoreServices::CheckForPendingReboot() entered
    16E0 20F0 05/06 14:17:09.723 16 engineservices.cpp(185)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CEngineServices::CheckForPendingReboot entered
    16E0 20F0 05/06 14:17:09.723 16 engineservices.cpp(197)  DA83D018-1264-450F-8DEB-C25DF7269344 WARNING Failed: Hr: = [0x80070002] : F: lVal : (UINT)RegOpenKeyExW((( HKEY ) (ULONG_PTR)((LONG)0x80000002) ), (LPCWSTR)rebootregkey, 0, ((((0x00020000L)) | (0x0001) | (0x0008) | (0x0010)) & (~(0x00100000L))), &key)
    16E0 22A4 05/06 14:19:09.695 09 coreservices.cpp(5453)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CCoreServices::CheckForPendingReboot() entered
    16E0 22A4 05/06 14:19:09.695 16 engineservices.cpp(185)  DA83D018-1264-450F-8DEB-C25DF7269344 NORMAL CEngineServices::CheckForPendingReboot entered
    16E0 22A4 05/06 14:19:09.695 16 engineservices.cpp(197)  DA83D018-1264-450F-8DEB-C25DF7269344 WARNING Failed: Hr: = [0x80070002] : F: lVal : (UINT)RegOpenKeyExW((( HKEY ) (ULONG_PTR)((LONG)0x80000002) ), (LPCWSTR)rebootregkey, 0, ((((0x00020000L)) | (0x0001) | (0x0008) | (0x0010)) & (~(0x00100000L))), &key)
    16E0 1C54 05/06 14:19:15.464 02 StubEventManager.cs(165)   WARNING Stale subscriber [65b348ca-f99a-4524-82d3-7fbd81e24f63] disposed


    NARS System Administrator
    Friday, May 6, 2011 2:27 PM
  • Hello,


    1.) 1088 248C 05/06 10:30:04.103 09 Catalog.cs(486) WARNING Attempt 1 failed with exception Microsoft.Internal.EnterpriseStorage.Dls.DB.NonFatalDbException: exception ---> System.Data.SqlClient.SqlException: Transaction (Process ID 53) was deadlocked on lock resources with another process and has been chosen as the deadlock victim.

    This shows up several times.  I'd use process monitor and process explorer to see which other processes may be locking files on this server.
    http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx
    http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx

    OR
    You can look at task manager and filter via Process ID while the job was running and then compare it to the logs.

     

    2.) See if this value exists in the registry:
    HKLM\Systtem\CurrentControlSet\Services\wbengine\SystemStateBackup\AllowSSBToAnyVolume:REG_DWORD:0x1
    Probably NOT the issue though.

    3.) %windir%\logs\WindowsServerBackup  backup logs are in etl. You will have to use another means in which to convert them into something readable like log parser.
    http://www.microsoft.com/downloads/en/details.aspx?FamilyID=890cd06b-abf8-4c25-91b2-f8d975cf8c07&displaylang=en

    Other than that, I'd look into opening up a support case with Microsoft for further investigation and a more indepth look.


    Thanks
    Shane

     

     

     

     

    Friday, May 6, 2011 7:34 PM
  • Ok thank you.  Any suggestions on how to begin a support case with them?  We have a Select Agreement and have one free case so I am definitely ready to get the ball rolling.  I was having the same issues with another 2008R2 server used for Operations Manager so I will put one in.

     

    thanks again,

    Zack

     


    NARS System Administrator
    Wednesday, May 18, 2011 3:57 PM
  • Hello,

    You can call 800-936-4900.

     

    Thanks
    Shane

    Wednesday, May 18, 2011 4:47 PM
  • ok thanks, I submitted a case.  I'll update this post with whatever solution they recommend (if it works).

     

     


    NARS System Administrator
    Wednesday, May 18, 2011 5:17 PM
  • Well it appears the issue was having the sql databases on the C volume.  After moving all of the system and user dbs to the D volume Friday I was able to take the initial BMR/Sysstate backup in DPM.  The syncronization also worked this morning at 1 am automatically.  So I guess the moral of the story is, keep your SQL dbs off the C volume because you never know what will break if you don't :)

     


    NARS System Administrator
    • Marked as answer by zzackw1975 Monday, May 23, 2011 1:56 PM
    Monday, May 23, 2011 1:56 PM