none
Fileserver Protection RRS feed

  • Question

  • We are just getting DPM setup for the first time, and I added my first PG being our filecluster. The system looks to backup the main volume the first time just fine, but then after the initial replica creation and recovery point is made each following sync fails. I run a consistency check and everything looks good again till the next sync and it fails again.

    Being new to this system I'm not really sure where to start troubleshooting this. The short term storage we have setup is a 1tb volume and currently we're backing up 350 gigs of data. The PG is set to sync every 15 minutes while retaining these for 5 days.

    Any direction anybody can point me would be greatly appreciated.

    Thank you

    Thursday, May 16, 2019 8:32 PM

Answers

  • Just wanted to check back in and let everyone know I ended up opening a case with Microsoft, and they were able to repair the replica on the DPM server. Since thing all our jobs have been running smoothly.

    Leon thank you for trying to get to the bottom of the problem.

    • Marked as answer by kstate CU IT Sunday, June 9, 2019 5:57 PM
    Sunday, June 9, 2019 5:57 PM

All replies

  • Hello,

    Could you provide us with some more information about your DPM environment?

    • What version of DPM you're using? In the DPM Administrator Console, click on the About button in the upper bar.
    • What is the operating system version of your DPM server?
    • What is the operating system version of your file server?

    You can view more information about the error in the Monitoring tab, provide us the error ID and error description.

    Best regards,
    Leon


    Blog: https://thesystemcenterblog.com LinkedIn:

    Thursday, May 16, 2019 8:48 PM
  • Sure thing

    DPM is 2019 10.19.58.0

    DPM Server is running Windows 2019

    File servers are both running Windows 2019

    Before I posted this I had recreated the PG and started the initial backup. It shows the job completed, but in the description it states ... "An unexpected error occurred while the job was running.(ID 104 Details: Cannot create a file when that file already exists (0x800700B7)).

    Then the Recovery Point also shows complete but has this in the description ... "Recovery point for Volume F:\ was created when the replica was inconsistent. Some data from this recovery point may contain partially synchronized data. (ID 30188)).

    Lastly it looks like the system tried to do a CC roughly 15 minutes later which it fails with the description of "DPM failed to clean up data of old incremental backups on the replica for Volume F:\ on (servername). Synchronization will fail until the replica cleanup succeeds. (ID 30134 Details: Cannot create a file when that file already exists (0x800700B7))

    Thursday, May 16, 2019 9:53 PM
  • Did you find any errors in the DPM log on the file server and on the DPM server?

    Do you have any antivirus software installed on the servers?
    If you do, you need to make sure that you have done the exclusions needed.


    Blog: https://thesystemcenterblog.com LinkedIn:

    Friday, May 17, 2019 6:57 AM
  • From the Failed Jobs logs I keep getting the following...

    "DPM failed to clean up data of old incremental backups on the replica for Volume F:\ on (server). Synchronization will fail until the replica cleanup succeeds. (ID 30134 Details: Cannot create a file when that file already exists (0x800700B7))"

    Then if I look under the event viewer under DPM Alerts I see...

    "The replica for  F:\ is currently being synchronized with consistency check. A consistency check can be started automatically or manually. To configure automatic consistency check options, modify this protection group using the Modify Protection Group Wizard. To start a manual consistency check, click Perform Consistency Check from the Actions pane on the Protection tab. (ID: 3104)"

    and

    "

    The replica of F:\ on (Server) is inconsistent with the protected data source. All protection activities for data source will fail until the replica is synchronized with consistency check. (ID: 3106)
    DPM failed to clean up data of old incremental backups on the replica for  F:\ on (Server). Synchronization will fail until the replica cleanup succeeds. (ID: 30134)"

    Oh forgot to mention we do not have any AV running on either the backup server or the server we're trying to backup. Completely removed it during this to make sure it wasn't causing issues.


    Monday, May 20, 2019 1:49 PM
  • Thanks for providing the logs, if this is a file server cluster, have you made sure to install the DPM agent on all file server cluster nodes?

    What type of disks is the file server cluster using, NTFS / ReFS?

    • Check the affected volume with chkdsk to see if there are any errors.
    • Try removing the protected data from the protection group, and then re-adding it.



    Blog: https://thesystemcenterblog.com LinkedIn:

    Monday, May 20, 2019 8:14 PM
  • DPM has been installed on both nodes. The drive in question is NTFS. I have gone through removing and re-adding the protection group a couple times.

    I have not done a chkdsk yet as it wants to take the drive offline which I can't do during the day. I can schedule this to be done tonight.

    In the failed job this morning it had this added information in the log. I'm wondering is there somewhere on this drive that I can go and clean up manually before trying to do a CC?

    DPM failed to clean up data of old incremental backups on the replica for Volume F:\ on (server). Synchronization will fail until the replica cleanup succeeds. (ID 30134 Details: Cannot create a file when that file already exists (0x800700B7))

    Monday, May 20, 2019 10:01 PM
  • Do you see any VSS errors in the Application event log of the file server cluster nodes?

    What is the result of the following command on both servers?

    vssadmin list providers


    Blog: https://thesystemcenterblog.com LinkedIn:

    Tuesday, May 21, 2019 9:00 AM
  • On both servers this is what is returned when running the vssadmin list command

    vssadmin list providers
    vssadmin 1.1 - Volume Shadow Copy Service administrative command-line tool
    (C) Copyright 2001-2013 Microsoft Corp.

    Provider name: 'Microsoft CSV Shadow Copy Helper Provider'
       Provider type: Software
       Provider Id: {26d02d81-6aac-4275-8504-b9c6edc5261d}
       Version: 1.0.0.1

    Provider name: 'Microsoft CSV Shadow Copy Provider'
       Provider type: Software
       Provider Id: {400a2ff4-5eb1-44b0-8a05-1fcac0bcf9ff}
       Version: 1.0.0.1

    Provider name: 'VSS Null Provider'
       Provider type: Software
       Provider Id: {8202aeda-45bd-48c4-b38b-ea1b7017aec3}
       Version: 10.19.58.0

    Provider name: 'Microsoft File Share Shadow Copy provider'
       Provider type: Fileshare
       Provider Id: {89300202-3cec-4981-9171-19f59559e0f2}
       Version: 1.0.0.1

    Provider name: 'Microsoft Software Shadow Copy provider 1.0'
       Provider type: System
       Provider Id: {b5946137-7b9f-4925-af80-51abd60b20d5}
       Version: 1.0.0.7

    Provider name: 'VSS Null Provider'
       Provider type: Fileshare
       Provider Id: {f4a69dd4-f712-40e3-a6b3-faeff03cb2b8}
       Version: 10.19.58.0

    The only VSS entries I see in the event viewer are "The VSS service is shutting down due to idle timeout"

    Tuesday, May 21, 2019 7:28 PM
  • All VSS providers look normal, nothing out of the ordinary there.

    Are you running data deduplication on the file server's volumes?

    Is this a normal file server cluster (with the file server cluster role) or a Scale-Out File Server (SoFS) cluster?


    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 22, 2019 1:02 PM
  • We do have deduplication running on this Drive, and it is a normal file server cluster

    Wednesday, May 22, 2019 4:34 PM
  • Are you able to disable the data deduplication and try backing up just to give it a test?

    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 22, 2019 4:58 PM
  • I turned off deduplication and still received the message about DPM failed to clean up data of old incremental backups on the replica for Volume F:\ on (server). Synchronization will fail until the replica cleanup succeeds. (ID 30134 Details: Cannot create a file when that file already exists (0x800700B7))
    Friday, May 24, 2019 9:49 PM
  • Can you check the DPM logs for any more clues / details?

    Protected computer log:

    • %ProgramFiles%\Microsoft Data Protection Manager\DPM\Temp\DPMRACurr.errlog

    DPM server log:

    • %ProgramFiles%\Microsoft System Center\DPM\DPM\Temp\MSDPMCurr.errlog


    Blog: https://thesystemcenterblog.com LinkedIn:

    Sunday, May 26, 2019 9:27 PM
  • hello,

    same problem here, fresh installed Windows 2019 server with DPM 2019. new Database.

    Fileserver is Windows server 2016 with dedub. old agent uninstalled, new agent installed.

    we had DPM 1807 and older version, they had no problem with it.

    regards

    Greg

    Monday, May 27, 2019 9:15 AM
  • Hello Greg,

    Do you also receive the exact same error and error ID?

    From the information gathered so far, both seems to be related to data deduplication, but we need to dig into the logs to confirm that this is actually the cause.


    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 29, 2019 2:16 PM
  • Hi,

    yes the same, but i found that on the DPM server my MTA folder was missing. i recreated it. know i waiting for Consistency check to finish (12TB)... hope i helps

    regards

    Wednesday, May 29, 2019 2:20 PM
  • Hopefully the consistency check will complete, let us know how it goes!

    From which path was the "MTA" folder missing?
    "C:\Program Files\Microsoft System Center\DPM\DPM\XSD\MTA" ?


    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 29, 2019 2:29 PM
  • hi,

    on the DPM server

    C:\Program Files\Microsoft System Center\DPM\DPM\Temp\MTA

    regards

    Wednesday, May 29, 2019 2:39 PM
  • i have the same problem
    Wednesday, May 29, 2019 2:43 PM
  • Please provide the information in the DPM logs so that we can together investigate if there's any more clues to this problem:

    Protected computer log:

    • %ProgramFiles%\Microsoft Data Protection Manager\DPM\Temp\DPMRACurr.errlog

    DPM server log:

    • %ProgramFiles%\Microsoft System Center\DPM\DPM\Temp\MSDPMCurr.errlog


    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 29, 2019 2:52 PM
  • Here is a portion (let me know if you need more) of the Protected computer log:

    0A80 12C0 05/29 15:30:01.303 22 ctimermgr.cpp(482) ACTIVITY CTimerMgr::TimerThread
    0A80 12C0 05/29 15:30:01.303 22 ctimermgr.cpp(495) [0000027C4EF56DA0] ACTIVITY CTimerMgr::TimerThreadInternal
    0A80 1BC4 05/29 15:30:01.303 03 timer.cpp(490) ACTIVITY CTimerMgr::TimerThread
    0A80 1BC4 05/29 15:30:01.303 03 timer.cpp(503) [0000027C4EF56BE0] ACTIVITY CTimerMgr::TimerThreadInternal
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(784) [0000027C4EF70DC0] ACTIVITY InitializeSecurity found 3 authorized entities
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(843) [0000027C4EF70DC0] ACTIVITY InitializeSecurity added COM perm for DPMRADCOMTrustedMachines
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(843) [0000027C4EF70DC0] ACTIVITY InitializeSecurity added COM perm for DPMRATrustedDPMRAs
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(850) [0000027C4EF70DC0] ACTIVITY InitializeSecurity added DM perm for DPMRADmTrustedMachines
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(97) NORMAL Found 1 writer account(s) under VSS access control.
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(165) NORMAL Added writer account [0] 'NT Authority\NetworkService' to the DACL.
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(1434) WARNING Failed: Hr: = [0x80070002] : Encountered Failure: : lVal : HRESULT_FROM_WIN32( ::RegGetValueW((( HKEY ) (ULONG_PTR)((LONG)0x80000002) ), L"Software\\Microsoft\\Microsoft Data Protection Manager\\Configuration", L"CredentialPassingAllowed", 0x00000010, 0, &dwRegValue, &dwBuffer) )
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(1443) NORMAL CredentialPassingAllowed: Checked reg value CredentialPassingAllowed and returning 0
    0A80 2280 05/29 15:30:01.318 03 runtime.cpp(977) NORMAL Setting DCOM Authn service to RPC_C_AUTHN_GSS_NEGOTIATE
    0A80 2280 05/29 15:30:01.318 22 genericthreadpool.cpp(824) [0000027C4EF70DC0] NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[20]
    0A80 2280 05/29 15:30:01.318 03 miscellaneousutils.cpp(1081) NORMAL Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    0A80 2280 05/29 15:30:01.334 20 commengine.cpp(345) [0000027C4EF682B0] ACTIVITY Hr: = [0x80070002] ConnectionNoActivityTimeout: 300
    0A80 2280 05/29 15:30:01.334 20 commengine.cpp(359) [0000027C4EF682B0] ACTIVITY Hr: = [0x80070002] m_dwConnectionNoActivityTimeoutForSlowReceiver: 3600
    0A80 2100 05/29 15:30:01.334 03 timer.cpp(490) ACTIVITY CTimerMgr::TimerThread
    0A80 2100 05/29 15:30:01.334 03 timer.cpp(503) [0000027C4FCCF6C8] ACTIVITY CTimerMgr::TimerThreadInternal
    0A80 2280 05/29 15:30:01.334 29 dpmra.cpp(176) [0000027C4EF04410] NORMAL CDPMRA::Initialize [0000027C4EF04410]
    0A80 2280 05/29 15:30:01.334 29 dpmra.cpp(639) NORMAL CDPMRA: Initialize globals
    0A80 2280 05/29 15:30:01.349 29 dpmra.cpp(626) ACTIVITY CDPMRA::AddSchemasToSchemaCacheForMTA => Initialize loaded schemas
    0A80 2280 05/29 15:30:01.365 29 dpmra.cpp(194) [0000027C4EF04410] NORMAL CDPMRA::Initialize loaded schemas 
    0A80 2280 05/29 15:30:01.365 22 genericthreadpool.cpp(75) [0000027C4EF046B0] NORMAL CGenericThreadPool: constructor
    0A80 2280 05/29 15:30:01.365 22 genericthreadpool.cpp(824) [0000027C4EF046B0] NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    0A80 2280 05/29 15:30:01.365 29 dpmra.cpp(276) [0000027C4EF04410] NORMAL CreateDefaultSubTask [0000027C4EF04410]
    0A80 2280 05/29 15:30:01.365 03 cbackupsubtasklimits.cpp(157) [0000027C4EF06130] NORMAL Resource Limit Config File: C:\Program Files\Microsoft Data Protection Manager\DPM\bin\DsResourceLimits.xml
    0A80 2280 05/29 15:30:01.365 03 cbackupsubtasklimits.cpp(163) [0000027C4EF06130] NORMAL Loaded DS Resource Limits
    0A80 2280 05/29 15:30:01.365 29 mtamethrottlehelper.cpp(112) [0000027C4FCC4E10] NORMAL Hr: = [0x80070002] Number of encryption threads = [2]
    0A80 2280 05/29 15:30:01.365 29 dpmra.cpp(204) [0000027C4EF04410] NORMAL Temporary storage path reg key found
    0A80 2280 05/29 15:30:01.365 29 dpmra.cpp(220) [0000027C4EF04410] NORMAL MTA Temp location Path = [C:\Program Files\Microsoft Data Protection Manager\DPM\temp\MTA\]
    0A80 2280 05/29 15:30:01.365 03 miscellaneousutils.cpp(1081) NORMAL Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    0A80 2280 05/29 15:30:01.365 03 service.cpp(298) [000000994247F730] ACTIVITY CService::AnnounceServiceStatus
    0A80 0A58 05/29 15:30:01.381 29 radefaultsubtask.cpp(248) [0000027C4FCDC230] 46A4BE08-9C1F-400D-B64C-3F8BB46AA7D5 ACTIVITY CMTADefaultSubTask::CommandReceivedSpecific => Command RefreshConnectivity Received
    0A80 2074 05/29 15:30:01.537 05 genericstatus.cpp(981) NORMAL CallUpdateQfesInstalledRegKey called in worker thread
    0A80 2074 05/29 15:30:01.537 05 genericstatus.cpp(1532) NORMAL Windows Qfe KB no: [KB948465] is not applicable on this machine
    0A80 2074 05/29 15:30:01.537 05 genericstatus.cpp(1532) NORMAL Windows Qfe KB no: [KB971394] is not applicable on this machine
    0A80 0A58 05/29 15:30:01.537 05 genericstatus.cpp(1327) [0000027C5020D5B0] 46A4BE08-9C1F-400D-B64C-3F8BB46AA7D5 NORMAL Wait for CallUpdateQfesInstalledRegKey succeeded. Returning m_QfesInstalled = 31
    0A80 0A58 05/29 15:30:01.537 03 schannelutils.cpp(129) 46A4BE08-9C1F-400D-B64C-3F8BB46AA7D5 WARNING Failed: Hr: = [0x80070002] : Unable to open RegKey [HKLM\Software\Microsoft\Microsoft Data Protection Manager\Agent\2.0\Certificates\(FQDN of Server1)]
    0A80 0A58 05/29 15:30:01.537 05 genericstatus.cpp(1733) [0000027C5020D5B0] 46A4BE08-9C1F-400D-B64C-3F8BB46AA7D5 NORMAL majorVerNum[10], minorVerNum[19], buildNum[58], hotfixNum[0]
    0A80 0D14 05/29 15:30:01.537 31 vssbaserequestor.cpp(51) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssBaseRequestor: constructor [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.537 31 vsssnapshotrequestor.cpp(104) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.537 03 cworkitem.cpp(429) [0000027C4EF04E28] 33E6D8DA-9632-418A-B69E-B2190172E403 ACTIVITY Idle Timer created with timeout = 390000
    0A80 0260 05/29 15:30:01.537 03 cworkitem.cpp(429) [0000027C4EF04C68] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 ACTIVITY Idle Timer created with timeout = 390000
    0A80 0D14 05/29 15:30:01.678 61 vainquirysubtask.cpp(215) [0000027C50C5E1A0] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL Writer metadata not needed for inquiry.
    0A80 0D14 05/29 15:30:01.678 61 inquirysubtask.cpp(1030) [0000027C50C5E1A0] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL ==>Tasks::CInquirySubTask::ExecuteInquiry
    0A80 0D14 05/29 15:30:01.678 61 necluster.cpp(84) [0000027C50DE0B20] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL ==>CNECluster::EnumerateClusterDetails
    0A80 0A58 05/29 15:30:01.693 03 cbackupworkitem.cpp(448) [0000027C4EF04BF0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL Processing app server account name [(domain)\(Server1)]
    0A80 0A58 05/29 15:30:01.709 03 cbackupworkitem.cpp(448) [0000027C4EF04BF0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL Processing app server account name [(domain)\(Server2)]
    0A80 0D14 05/29 15:30:01.724 61 necluster.cpp(84) [0000027C50DE0B20] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL <--CNECluster::EnumerateClusterDetails
    0A80 0D14 05/29 15:30:01.724 61 inquirysubtask.cpp(1030) [0000027C50C5E1A0] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL <--Tasks::CInquirySubTask::ExecuteInquiry
    0A80 0260 05/29 15:30:01.724 61 inquirysubtask.cpp(457) [0000027C50C5E1A0] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL Sending final response with 2 records
    0A80 0260 05/29 15:30:01.740 61 inquirysubtask.cpp(989) [0000027C50C5E1A0] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CInquirySubTask::Inquiry finished with status [0000000000]
    0A80 0D14 05/29 15:30:01.740 03 cworkitem.cpp(23) [0000027C4EF04BF0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 ACTIVITY WorkItem stopping
    0A80 0260 05/29 15:30:01.756 31 vsssnapshotrequestor.cpp(122) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.756 31 vsssnapshotrequestor.cpp(2182) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssSnapshotRequestor::CleanUp [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.756 31 vsssnapshotrequestor.cpp(1768) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssSnapshotRequestor::ReleaseVolumesForSnapshot [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.756 31 vssbaserequestor.cpp(69) [0000027C50C5E4F8] 33E6D8DA-9632-418A-B69E-B2190172E403 NORMAL CVssBaseRequestor: destructor [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.756 03 cworkitem.cpp(23) [0000027C4EF04DB0] 33E6D8DA-9632-418A-B69E-B2190172E403 ACTIVITY WorkItem stopping
    0A80 0260 05/29 15:30:01.834 31 vssbaserequestor.cpp(51) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssBaseRequestor: constructor [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.834 31 vsssnapshotrequestor.cpp(104) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000027C50C5E4F8]
    0A80 0260 05/29 15:30:01.834 03 cworkitem.cpp(429) [0000027C4EF04808] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 ACTIVITY Idle Timer created with timeout = 390000
    0A80 0260 05/29 15:30:01.834 61 vainquirysubtask.cpp(215) [0000027C50C5E1A0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL Writer metadata not needed for inquiry.
    0A80 0260 05/29 15:30:01.834 61 inquirysubtask.cpp(1030) [0000027C50C5E1A0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL ==>Tasks::CInquirySubTask::ExecuteInquiry
    0A80 0260 05/29 15:30:01.834 61 necluster.cpp(84) [0000027C50DE0A00] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL ==>CNECluster::EnumerateClusterDetails
    0A80 0260 05/29 15:30:01.881 61 necluster.cpp(84) [0000027C50DE0A00] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL <--CNECluster::EnumerateClusterDetails
    0A80 0260 05/29 15:30:01.881 61 inquirysubtask.cpp(1030) [0000027C50C5E1A0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL <--Tasks::CInquirySubTask::ExecuteInquiry
    0A80 0D14 05/29 15:30:01.881 61 inquirysubtask.cpp(457) [0000027C50C5E1A0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL Sending final response with 2 records
    0A80 0D14 05/29 15:30:01.881 61 inquirysubtask.cpp(989) [0000027C50C5E1A0] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CInquirySubTask::Inquiry finished with status [0000000000]
    0A80 0D14 05/29 15:30:01.881 31 vsssnapshotrequestor.cpp(122) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.881 31 vsssnapshotrequestor.cpp(2182) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssSnapshotRequestor::CleanUp [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.881 31 vsssnapshotrequestor.cpp(1768) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssSnapshotRequestor::ReleaseVolumesForSnapshot [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.881 31 vssbaserequestor.cpp(69) [0000027C50C5E4F8] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 NORMAL CVssBaseRequestor: destructor [0000027C50C5E4F8]
    0A80 0D14 05/29 15:30:01.881 03 cworkitem.cpp(23) [0000027C4EF04790] 3C90141D-9DE9-47B6-8EC3-86578CE2FB67 ACTIVITY WorkItem stopping
    0A80 2390 05/29 15:30:18.493 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:30:18.493 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:31:18.744 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:31:18.744 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:31:45.277 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:32:19.062 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:32:19.062 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:33:19.300 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:33:19.300 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:34:19.524 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 2390 05/29 15:34:19.524 03 service.cpp(147) [000000994247F730] ACTIVITY CService::ServiceHandlerExInternal
    0A80 1BC4 05/29 15:35:01.900 03 runtime.cpp(1496) [0000027C4EF70DC0] NORMAL CDLSRuntime::ProcessIdleTimeout
    0A80 1BC4 05/29 15:35:01.900 03 runtime.cpp(604) [0000027C4EF70DC0] NORMAL CDLSRuntime::Uninitialize, bForce: 0
    0A80 1BC4 05/29 15:35:01.900 05 genericagent.cpp(273) [0000027C4EF04410] NORMAL Agent Can Shutdown if there is only default wokitem active[1]
    0A80 1BC4 05/29 15:35:01.900 29 dpmra.cpp(378) [0000027C4EF04410] NORMAL CDPMRA::Shutting down dpmra, force-shutdown :yes
    0A80 1BC4 05/29 15:35:01.900 03 cworkitem.cpp(328) [0000027C4EFC6D90] NORMAL Timing out WI [0000027C4EFC6D90], WI GUID = {B71B4544-7067-4A30-B5FB-BA320B10D82A}, ..last DM activity happened 913808250msec back, WI Idle Timeout = 390000msec
    0A80 1BC4 05/29 15:35:01.900 22 genericthreadpool.cpp(684) [0000027C4EF046B0] NORMAL CGenericThreadPool: Waiting for threads to exit
    0A80 1BC4 05/29 15:35:03.915 22 genericthreadpool.cpp(684) [0000027C4EF70DC0] NORMAL CGenericThreadPool: Waiting for threads to exit
    0A80 1BC4 05/29 15:35:05.931 29 dpmra.cpp(142) [0000027C4EF04410] NORMAL CDPMRA: destructor [0000027C4EF04410]
    0A80 2100 05/29 15:35:05.947 03 timer.cpp(513) [0000027C4FCCF6C8] ACTIVITY Shutting down timer thread.
    0A80 1BC4 05/29 15:35:05.947 03 service.cpp(81) ACTIVITY CService::StopThisService
    0A80 1BC4 05/29 15:35:05.947 03 service.cpp(281) [000000994247F730] ACTIVITY CService::StopService()
    0A80 2280 05/29 15:35:05.947 03 service.cpp(298) [000000994247F730] ACTIVITY CService::AnnounceServiceStatus

    Wednesday, May 29, 2019 3:50 PM
  • @Gregor: What build of Windows Server 2016 are you running on your fileserver? Also are you running with ReFS or NTFS file system on the fileserver's disk(s)?


    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 29, 2019 10:48 PM
  • @kstate CU IT: Can you provide the logs of your cluster nodes (protected computers) as well? Thanks.

    Blog: https://thesystemcenterblog.com LinkedIn:

    Wednesday, May 29, 2019 11:16 PM
  • @Leon

    Version 1607(OS Build 14393.2969)

    NTFS

    Thursday, May 30, 2019 7:14 AM
  • hmm, check finished. i have 1 recovery point, but if 1 want another one i get this:

    why is only synchronize greyed out? never see this before..


    Thursday, May 30, 2019 7:23 AM
  • oke, error is back:

    DPM failed to clean up data of old incremental backups on the replica for Volume H:\ on servername. Synchronization will fail until the replica cleanup succeeds. (ID 30134 Details: Cannot create a file when that file already exists (0x800700B7))

    Fileserver log:

    0A50    0F08    05/30    07:29:31.574    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:29:31.950    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    1D44    05/30    07:30:00.953    29    radefaultsubtask.cpp(248)    [00000215E1B5A6C0]    E0E78F33-298F-4C3F-A255-1D80C6E2EBE7    ACTIVITY    CMTADefaultSubTask::CommandReceivedSpecific => Command RefreshConnectivity Received
    0A50    0878    05/30    07:30:00.953    05    genericstatus.cpp(981)            NORMAL    CallUpdateQfesInstalledRegKey called in worker thread
    0A50    0878    05/30    07:30:00.953    05    genericstatus.cpp(1532)            NORMAL    Windows Qfe KB no: [KB948465] is not applicable on this machine
    0A50    0878    05/30    07:30:00.953    05    genericstatus.cpp(1532)            NORMAL    Windows Qfe KB no: [KB971394] is not applicable on this machine
    0A50    1D44    05/30    07:30:00.953    05    genericstatus.cpp(1327)    [00000215E0494E80]    E0E78F33-298F-4C3F-A255-1D80C6E2EBE7    NORMAL    Wait for CallUpdateQfesInstalledRegKey succeeded. Returning m_QfesInstalled = 31
    0A50    1D44    05/30    07:30:00.953    03    schannelutils.cpp(129)        E0E78F33-298F-4C3F-A255-1D80C6E2EBE7    WARNING    Failed: Hr: = [0x80070002] : Unable to open RegKey [HKLM\Software\Microsoft\Microsoft Data Protection Manager\Agent\2.0\Certificates\titan.evopro.hu]
    0A50    1D44    05/30    07:30:00.953    05    genericstatus.cpp(1733)    [00000215E0494E80]    E0E78F33-298F-4C3F-A255-1D80C6E2EBE7    NORMAL    majorVerNum[10], minorVerNum[19], buildNum[58], hotfixNum[0]
    0A50    1D44    05/30    07:30:23.268    31    vssbaserequestor.cpp(51)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssBaseRequestor: constructor [00000215E1B454A8]
    0A50    1D44    05/30    07:30:23.268    31    vsssnapshotrequestor.cpp(104)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssSnapshotRequestor::CVssSnapshotRequestor [00000215E1B454A8]
    0A50    1D44    05/30    07:30:23.284    03    cworkitem.cpp(429)    [00000215E276C888]    F29BC47A-D65F-47D2-989E-90E01729925B    ACTIVITY    Idle Timer created with timeout = 390000
    0A50    1D44    05/30    07:30:23.393    61    vainquirysubtask.cpp(215)    [00000215E1B45150]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    Writer metadata not needed for inquiry.
    0A50    1D44    05/30    07:30:23.393    61    inquirysubtask.cpp(1030)    [00000215E1B45150]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    ==>Tasks::CInquirySubTask::ExecuteInquiry
    0A50    1D44    05/30    07:30:23.440    61    inquirysubtask.cpp(1030)    [00000215E1B45150]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    <--Tasks::CInquirySubTask::ExecuteInquiry
    0A50    1214    05/30    07:30:23.440    61    inquirysubtask.cpp(457)    [00000215E1B45150]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    Sending final response with 1 records
    0A50    1214    05/30    07:30:23.456    61    inquirysubtask.cpp(989)    [00000215E1B45150]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CInquirySubTask::Inquiry finished with status [0000000000]
    0A50    1214    05/30    07:30:23.456    31    vsssnapshotrequestor.cpp(122)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssSnapshotRequestor::~CVssSnapshotRequestor [00000215E1B454A8]
    0A50    1214    05/30    07:30:23.456    31    vsssnapshotrequestor.cpp(2182)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssSnapshotRequestor::CleanUp [00000215E1B454A8]
    0A50    1214    05/30    07:30:23.456    31    vsssnapshotrequestor.cpp(1768)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssSnapshotRequestor::ReleaseVolumesForSnapshot [00000215E1B454A8]
    0A50    1214    05/30    07:30:23.456    31    vssbaserequestor.cpp(69)    [00000215E1B454A8]    F29BC47A-D65F-47D2-989E-90E01729925B    NORMAL    CVssBaseRequestor: destructor [00000215E1B454A8]
    0A50    1214    05/30    07:30:23.456    03    cworkitem.cpp(23)    [00000215E276C810]    F29BC47A-D65F-47D2-989E-90E01729925B    ACTIVITY    WorkItem stopping
    0A50    0F08    05/30    07:30:31.660    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:30:32.035    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:31:31.745    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:31:32.120    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:32:31.831    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:32:32.206    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:33:31.916    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:33:32.291    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:34:13.264    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:34:32.001    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    0F08    05/30    07:34:32.376    03    service.cpp(147)    [00000064405FFB20]        ACTIVITY    CService::ServiceHandlerExInternal
    0A50    1E4C    05/30    07:35:23.460    03    runtime.cpp(1496)    [00000215E051F8D0]        NORMAL    CDLSRuntime::ProcessIdleTimeout
    0A50    1E4C    05/30    07:35:23.460    03    runtime.cpp(604)    [00000215E051F8D0]        NORMAL    CDLSRuntime::Uninitialize, bForce: 0
    0A50    1E4C    05/30    07:35:23.460    05    genericagent.cpp(273)    [00000215E04A8D70]        NORMAL    Agent Can Shutdown if there is only default wokitem active[1]
    0A50    1E4C    05/30    07:35:23.460    29    dpmra.cpp(378)    [00000215E04A8D70]        NORMAL    CDPMRA::Shutting down dpmra, force-shutdown :yes
    0A50    1E4C    05/30    07:35:23.460    03    cworkitem.cpp(328)    [00000215E049B950]        NORMAL    Timing out WI [00000215E049B950], WI GUID = {B71B4544-7067-4A30-B5FB-BA320B10D82A}, ..last DM activity happened 216360343msec back, WI Idle Timeout = 390000msec
    0A50    1E4C    05/30    07:35:23.460    22    genericthreadpool.cpp(684)    [00000215E04ACFE0]        NORMAL    CGenericThreadPool: Waiting for threads to exit
    0A50    1E4C    05/30    07:35:25.461    22    genericthreadpool.cpp(684)    [00000215E051F8D0]        NORMAL    CGenericThreadPool: Waiting for threads to exit
    0A50    1E4C    05/30    07:35:27.476    29    dpmra.cpp(142)    [00000215E04A8D70]        NORMAL    CDPMRA: destructor [00000215E04A8D70]
    0A50    1FE8    05/30    07:35:27.492    03    timer.cpp(513)    [00000215E0A6E678]        ACTIVITY    Shutting down timer thread.
    0A50    1E4C    05/30    07:35:27.492    03    service.cpp(81)            ACTIVITY    CService::StopThisService
    0A50    1E4C    05/30    07:35:27.492    03    service.cpp(281)    [00000064405FFB20]        ACTIVITY    CService::StopService()
    0A50    1C94    05/30    07:35:27.492    03    service.cpp(298)    [00000064405FFB20]        ACTIVITY    CService::AnnounceServiceStatus
    0208    1890    05/30    07:44:32.790    22    ctimermgr.cpp(482)            ACTIVITY    CTimerMgr::TimerThread
    0208    1D90    05/30    07:44:32.790    03    timer.cpp(490)            ACTIVITY    CTimerMgr::TimerThread
    0208    1890    05/30    07:44:32.790    22    ctimermgr.cpp(495)    [00000227EE946070]        ACTIVITY    CTimerMgr::TimerThreadInternal
    0208    1D90    05/30    07:44:32.790    03    timer.cpp(503)    [00000227EE9457B0]        ACTIVITY    CTimerMgr::TimerThreadInternal
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(784)    [00000227EE991B10]        ACTIVITY    InitializeSecurity found 3 authorized entities
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(843)    [00000227EE991B10]        ACTIVITY    InitializeSecurity added COM perm for DPMRADCOMTrustedMachines
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(843)    [00000227EE991B10]        ACTIVITY    InitializeSecurity added COM perm for DPMRATrustedDPMRAs
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(850)    [00000227EE991B10]        ACTIVITY    InitializeSecurity added DM perm for DPMRADmTrustedMachines
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(97)            NORMAL    Found 1 writer account(s) under VSS access control.
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(165)            NORMAL    Added writer account [0] 'NT Authority\NetworkService' to the DACL.
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(1434)            WARNING    Failed: Hr: = [0x80070002] : Encountered Failure: : lVal : HRESULT_FROM_WIN32( ::RegGetValueW((( HKEY ) (ULONG_PTR)((LONG)0x80000002) ), L"Software\\Microsoft\\Microsoft Data Protection Manager\\Configuration", L"CredentialPassingAllowed", 0x00000010, 0, &dwRegValue, &dwBuffer) )
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(1443)            NORMAL    CredentialPassingAllowed: Checked reg value CredentialPassingAllowed and returning 0
    0208    1608    05/30    07:44:32.790    03    runtime.cpp(977)            NORMAL    Setting DCOM Authn service to RPC_C_AUTHN_GSS_NEGOTIATE
    0208    1608    05/30    07:44:32.790    22    genericthreadpool.cpp(824)    [00000227EE991B10]        NORMAL    Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[20]
    0208    1608    05/30    07:44:32.790    03    miscellaneousutils.cpp(1081)            NORMAL    Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    0208    1608    05/30    07:44:32.790    20    commengine.cpp(345)    [00000227EEF6B300]        ACTIVITY    Hr: = [0x80070002] ConnectionNoActivityTimeout: 300
    0208    1608    05/30    07:44:32.790    20    commengine.cpp(359)    [00000227EEF6B300]        ACTIVITY    Hr: = [0x80070002] m_dwConnectionNoActivityTimeoutForSlowReceiver: 3600
    0208    118C    05/30    07:44:32.790    03    timer.cpp(490)            ACTIVITY    CTimerMgr::TimerThread
    0208    118C    05/30    07:44:32.790    03    timer.cpp(503)    [00000227EEFD75B8]        ACTIVITY    CTimerMgr::TimerThreadInternal
    0208    1608    05/30    07:44:32.790    29    dpmra.cpp(176)    [00000227EE920E00]        NORMAL    CDPMRA::Initialize [00000227EE920E00]
    0208    1608    05/30    07:44:32.790    29    dpmra.cpp(639)            NORMAL    CDPMRA: Initialize globals
    0208    1608    05/30    07:44:32.806    29    dpmra.cpp(626)            ACTIVITY    CDPMRA::AddSchemasToSchemaCacheForMTA => Initialize loaded schemas
    0208    1608    05/30    07:44:32.806    29    dpmra.cpp(194)    [00000227EE920E00]        NORMAL    CDPMRA::Initialize loaded schemas
    0208    1608    05/30    07:44:32.806    22    genericthreadpool.cpp(75)    [00000227EE920C40]        NORMAL    CGenericThreadPool: constructor
    0208    1608    05/30    07:44:32.806    22    genericthreadpool.cpp(824)    [00000227EE920C40]        NORMAL    Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    0208    1608    05/30    07:44:32.806    29    dpmra.cpp(276)    [00000227EE920E00]        NORMAL    CreateDefaultSubTask [00000227EE920E00]
    0208    1608    05/30    07:44:32.806    03    cbackupsubtasklimits.cpp(157)    [00000227EFF5D9F0]        NORMAL    Resource Limit Config File: C:\Program Files\Microsoft Data Protection Manager\DPM\bin\DsResourceLimits.xml
    0208    1608    05/30    07:44:32.806    03    cbackupsubtasklimits.cpp(163)    [00000227EFF5D9F0]        NORMAL    Loaded DS Resource Limits
    0208    1608    05/30    07:44:32.806    29    mtamethrottlehelper.cpp(112)    [00000227EEF6AFD0]        NORMAL    Hr: = [0x80070002] Number of encryption threads = [2]
    0208    1608    05/30    07:44:32.806    29    dpmra.cpp(204)    [00000227EE920E00]        NORMAL    Temporary storage path reg key found
    0208    1608    05/30    07:44:32.806    29    dpmra.cpp(220)    [00000227EE920E00]        NORMAL    MTA Temp location Path = [C:\Program Files\Microsoft Data Protection Manager\DPM\temp\MTA\]
    0208    1608    05/30    07:44:32.806    03    miscellaneousutils.cpp(1081)            NORMAL    Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    0208    1608    05/30    07:44:32.806    03    service.cpp(298)    [00000067E3CBFD80]        ACTIVITY    CService::AnnounceServiceStatus
    0208    1E20    05/30    07:44:32.821    03    cworkitem.cpp(429)    [00000227EE920938]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    ACTIVITY    Idle Timer created with timeout = 390000
    0208    00E0    05/30    07:44:32.853    03    service.cpp(147)    [00000067E3CBFD80]        ACTIVITY    CService::ServiceHandlerExInternal
    0000    1E20    05/30    07:44:32.868    00    nativeutils.hpp(42)        A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    Unable to get registry value for: Software\Microsoft\Microsoft Data Protection Manager\Agent\ClientProtection\WaitInMSPerRequestForClientRead
    0208    1E20    05/30    07:44:32.868    31    dllmain.cpp(36)        A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    FileWriterHelperPlugin: DLL_PROCESS_ATTACH
    0208    1E20    05/30    07:44:32.884    31    vssbaserequestor.cpp(51)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssBaseRequestor: constructor [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.884    31    vsssnapshotrequestor.cpp(104)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor::CVssSnapshotRequestor [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.884    31    vssbaserequestor.cpp(88)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssBaseRequestor::Initialize [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.884    31    vsssnapshotrequestor.cpp(205)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor::InitializeSnapshotCreation [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.900    31    vsssnapshotrequestor.cpp(658)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor::SetContext [00000227EFF4B540] m_snapshotInfo.snapshotContext 16
    0208    1E20    05/30    07:44:32.900    03    miscellaneousutils.cpp(1081)        A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    0208    1E20    05/30    07:44:32.900    31    vsssnapshotrequestor.cpp(409)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor::AddVolumeForSnapshot [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.900    31    vsssnapshotrequestor.cpp(441)        A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    ssLocalVolumeGuid = [\\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}\], ssClusterVolGuid=[\\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}\]
    0208    1E20    05/30    07:44:32.900    31    vsssnapshotrequestor.cpp(477)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor::AddVolumeForSnapshot [00000227EFF4B540]
    0208    1E20    05/30    07:44:32.900    31    vsssnapshotrequestor.cpp(500)    [00000227EFF4B540]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CVssSnapshotRequestor: AddVolumeForSnapshot - Marked volume \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}\ to be snapshot
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(32)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournalHelper::ActivateJournal Volume Path = \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}\, max size = 0x0000000012C00000, alloc delta = 0x0000000001E00000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(527)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(545)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}, Volume Handle = 94c
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(123)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    UsnJournalID    = 0x01D3E4B5BD05E763
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(124)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    FirstUsn        = 0x000000069EE00000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(125)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    NextUsn         = 0x00000006CA7D2720
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(126)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    LowestValidUsn  = 0x0000000000000000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(127)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    MaxUsn          = 0x7FFFFFFFFFFF0000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(128)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    MaximumSize     = 0x0000000025800000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(129)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    AllocationDelta = 0x0000000009600000
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(159)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    Need to reset USN false
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(527)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(545)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{0abbdd9e-a18d-4407-a995-7c064f07dbe5}, Volume Handle = 94c
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(466)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    CUsnJournalHelper::GetNextUsnInternal(vol:94c)
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(488)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    UsnJournalID    = 0x01D3E4B5BD05E763
    0208    1E20    05/30    07:44:32.900    18    usnjournalhelper.cpp(489)    [00000067E4BFF070]    A7CF1D5E-2853-48D5-B5B5-FA6BC3D76A6A    NORMAL    First


    Thursday, May 30, 2019 8:34 AM
  • dpm server:

    2798    225C    05/30    07:15:21.145    16    engineservices.cpp(405)            NORMAL    CEngineServices::GetOSVersionOnDPMServer entered
    2798    2150    05/30    07:15:32.022    17    intentservices.cpp(2805)            NORMAL    CIntentServices::GetCBPVersionOnDPMServer
    2798    2150    05/30    07:15:32.027    09    serviceutils.cpp(617)            WARNING    Caught Dls exception: Microsoft.Internal.EnterpriseStorage.Dls.Utils.DlsException: Exception of type 'Microsoft.Internal.EnterpriseStorage.Dls.Utils.DlsException' was thrown.
    2798    2150    05/30    07:15:32.027    09    serviceutils.cpp(617)            WARNING       at Microsoft.Internal.EnterpriseStorage.Dls.Utils.ApplicationSettings.GetCBPVersion(String& version)
    2798    2150    05/30    07:15:32.027    09    serviceutils.cpp(617)            WARNING       at Microsoft.Internal.EnterpriseStorage.Dls.Engine.CIntentServices.GetCBPVersionOnDPMServer(UInt16** cbpVersionBSTR)
    2798    2150    05/30    07:15:32.027    09    serviceutils.cpp(617)            WARNING       at Microsoft.Internal.EnterpriseStorage.Dls.Engine.CCoreServices.GetCBPVersionOnDPMServer(CCoreServices* , UInt16** cbpVersionBSTR, tagSAFEARRAY** exceptionResult)
    2798    2150    05/30    07:15:32.027    09    serviceutils.cpp(617)            WARNING    *** Mojito error was: CBPNotInstalled; 0; None
    2798    2150    05/30    07:15:32.385    09    coreservices.cpp(9337)            NORMAL    CCoreServices::CheckProductExpiry() entered
    2798    2150    05/30    07:15:32.385    16    engineservices.cpp(297)            NORMAL    CEngineServices::CheckProductExpiry entered
    2798    2150    05/30    07:15:32.505    17    intentservices.cpp(134)            NORMAL    CIntentServices::SetGlobalProperty(). bstrPropertyName=DPMUIUsedLocales, bstrPropertyValue=en-US,en-GB,hu-HU
    2798    2150    05/30    07:15:32.509    17    intentservices.cpp(134)            NORMAL    CIntentServices::SetGlobalProperty(). bstrPropertyName=DPMUIUsedLocales, bstrPropertyValue=en-US,en-GB,hu-HU
    2798    2150    05/30    07:15:34.622    09    coreservices.cpp(9337)            NORMAL    CCoreServices::CheckProductExpiry() entered
    2798    2150    05/30    07:15:34.622    16    engineservices.cpp(297)            NORMAL    CEngineServices::CheckProductExpiry entered
    2798    2150    05/30    07:16:02.398    17    intentservices.cpp(965)            NORMAL    CIntentServices::TriggerValidationForRepilcaInInvalidStateAlert(). AlertId={281F7073-0C0D-4DE1-80AF-D2F8885CD46E}
    2798    2150    05/30    07:16:02.413    16    JobManager.cs(456)            NORMAL     AddJobIdToResumeBackupJobs job:e043f99c-13ab-45ba-92d2-245498ed64b3
    2798    2150    05/30    07:16:02.429    27    PRMCatalog.cs(11377)            NORMAL    Agent Version number is 10.19.58.0
    2798    2150    05/30    07:16:02.429    27    PRMCatalog.cs(9296)            WARNING    Not a cluster object backup.contoso.com
    2798    2150    05/30    07:16:02.429    27    PRMCatalog.cs(9328)            NORMAL    OSVersion for: backup.contoso.com is 10.0.17763
    2798    2150    05/30    07:16:02.429    27    PRMCatalog.cs(9296)            WARNING    Not a cluster object titan.contoso.com
    2798    2150    05/30    07:16:02.429    27    PRMCatalog.cs(9328)            NORMAL    OSVersion for: titan.contoso.com is 10.0.14393
    2798    2150    05/30    07:16:02.445    27    PRMCatalog.cs(11377)            NORMAL    Agent Version number is 10.19.58.0
    2798    2150    05/30    07:16:02.445    27    PRMCatalog.cs(9296)            WARNING    Not a cluster object backup.contoso.com
    2798    2150    05/30    07:16:02.445    27    PRMCatalog.cs(9328)            NORMAL    OSVersion for: backup.contoso.com is 10.0.17763
    2798    2150    05/30    07:16:02.445    27    PRMCatalog.cs(9296)            WARNING    Not a cluster object titan.contoso.com
    2798    2150    05/30    07:16:02.445    27    PRMCatalog.cs(9328)            NORMAL    OSVersion for: titan.contoso.com is 10.0.14393
    2798    2150    05/30    07:16:02.445    16    JobDefinitionManager.cs(129)            NORMAL     AddJobDefinition:f4a9aaa8-22f3-4866-8161-a9604be3a2f0
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(349)            NORMAL     Trigger job:f4a9aaa8-22f3-4866-8161-a9604be3a2f0 with id:e043f99c-13ab-45ba-92d2-245498ed64b3
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL    JobContext Xml is <?xml version="1.0" encoding="utf-16"?>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL    <AdhocJobsContext xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <ActionId>99d57936-643b-484b-9a78-8ecd7a6bb032</ActionId>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <ScomAlertTicketId />
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <TriggeredBy>evopro\mottl.gergely</TriggeredBy>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <TargetName>H:\(titan.contoso.com)</TargetName>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <DpmObjectID>40794e40-6319-4498-88de-ebc21b659848</DpmObjectID>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <StartTime>2019-05-30T07:16:02.3671438Z</StartTime>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <IsTriggeredFromDPM>true</IsTriggeredFromDPM>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <TargetObjectType>Datasource</TargetObjectType>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <AlertName>RunVerificationJob</AlertName>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL      <AdhocJobType>ResumeBackupsOnAlert</AdhocJobType>
    2798    2150    05/30    07:16:02.445    16    JobManager.cs(353)            NORMAL    </AdhocJobsContext>
    2798    2150    05/30    07:16:02.445    16    Task.cs(235)            NORMAL     Changing task state from 'Invalid' -> 'Start' (a5e0105b-d4eb-478f-a298-258a3f830d66)
    2798    2150    05/30    07:16:02.445    16    Task.cs(235)            NORMAL     Changing task state from 'Invalid' -> 'Start' (5d30018e-df77-456a-9074-f64e343d9a2f)
    2798    2150    05/30    07:16:02.445    16    Task.cs(235)            NORMAL     Changing task state from 'Invalid' -> 'Start' (775f2ed0-23fa-477a-9882-42fa3e25ba40)
    2798    2150    05/30    07:16:02.460    02    EventManager.cs(98)            NORMAL    Publishing event from ActiveJob.cs(299): JobStateChange, [JobID=e043f99c-13ab-45ba-92d2-245498ed64b3]
    2798    2978    05/30    07:16:02.460    16    ActiveJob.cs(317)            NORMAL     Start execution of job:'e043f99c-13ab-45ba-92d2-245498ed64b3' in state:'Start'
    2798    2978    05/30    07:16:02.460    68    ActivityWindow.cs(75)            NORMAL     Add new wait : e043f99c-13ab-45ba-92d2-245498ed64b3(wait until: 2019. június 19., szerda) @ 2019. május 30., csütörtökUTC
    2798    2978    05/30    07:16:02.460    68    ActivityWindow.cs(198)            NORMAL     Setting timer for '1727999,9843759's...
    2798    2978    05/30    07:16:02.460    16    ActiveJob.cs(1081)            NORMAL     Changing state of job: 'e043f99c-13ab-45ba-92d2-245498ed64b3' from 'Start' -> 'GenerateWorkplan'
    2798    2978    05/30    07:16:02.460    02    EventManager.cs(98)            NORMAL    Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=e043f99c-13ab-45ba-92d2-245498ed64b3]
    2798    2978    05/30    07:16:02.460    16    ActiveJob.cs(581)            NORMAL     Begin GenerateWorkplan:JobID=e043f99c-13ab-45ba-92d2-245498ed64b3, ItemID=a5e0105b-d4eb-478f-a298-258a3f830d66
    2798    2978    05/30    07:16:02.460    01    TaskExecutor.cs(81)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Entering
    2798    2978    05/30    07:16:02.460    02    EventManager.cs(98)            NORMAL    Publishing event from TaskExecutor.cs(107): TaskCreated, [TaskID=a5e0105b-d4eb-478f-a298-258a3f830d66]
    2798    2978    05/30    07:16:02.476    01    TaskExecutor.cs(127)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Finished (success=True), executing GenerateWorkplanCallback
    2798    2978    05/30    07:16:02.476    16    Task.cs(235)            NORMAL     Changing task state from 'Start' -> 'GenerateWorkplan' (a5e0105b-d4eb-478f-a298-258a3f830d66)
    2798    2978    05/30    07:16:02.476    16    ActiveJob.cs(581)            NORMAL     Begin GenerateWorkplan:JobID=e043f99c-13ab-45ba-92d2-245498ed64b3, ItemID=5d30018e-df77-456a-9074-f64e343d9a2f
    2798    2978    05/30    07:16:02.476    01    TaskExecutor.cs(81)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Entering
    2798    2978    05/30    07:16:02.476    02    EventManager.cs(98)            NORMAL    Publishing event from TaskExecutor.cs(107): TaskCreated, [TaskID=5d30018e-df77-456a-9074-f64e343d9a2f]
    2798    2978    05/30    07:16:02.492    01    TaskExecutor.cs(127)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Finished (success=True), executing GenerateWorkplanCallback
    2798    2978    05/30    07:16:02.492    16    Task.cs(235)            NORMAL     Changing task state from 'Start' -> 'GenerateWorkplan' (5d30018e-df77-456a-9074-f64e343d9a2f)
    2798    22B4    05/30    07:16:02.492    16    ActiveJob.cs(581)            NORMAL     Begin GenerateWorkplan:JobID=e043f99c-13ab-45ba-92d2-245498ed64b3, ItemID=775f2ed0-23fa-477a-9882-42fa3e25ba40
    2798    22B4    05/30    07:16:02.492    01    TaskExecutor.cs(81)        775F2ED0-23FA-477A-9882-42FA3E25BA40    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Entering
    2798    22B4    05/30    07:16:02.492    02    EventManager.cs(98)            NORMAL    Publishing event from TaskExecutor.cs(107): TaskCreated, [TaskID=775f2ed0-23fa-477a-9882-42fa3e25ba40]
    2798    22B4    05/30    07:16:02.507    01    TaskExecutor.cs(127)        775F2ED0-23FA-477A-9882-42FA3E25BA40    NORMAL    GenerateWorkplan(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Finished (success=True), executing GenerateWorkplanCallback
    2798    22B4    05/30    07:16:02.507    16    Task.cs(235)            NORMAL     Changing task state from 'Start' -> 'GenerateWorkplan' (775f2ed0-23fa-477a-9882-42fa3e25ba40)
    2798    22B4    05/30    07:16:02.507    16    ActiveJob.cs(1081)            NORMAL     Changing state of job: 'e043f99c-13ab-45ba-92d2-245498ed64b3' from 'GenerateWorkplan' -> 'Execute'
    2798    22B4    05/30    07:16:02.507    02    EventManager.cs(98)            NORMAL    Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=e043f99c-13ab-45ba-92d2-245498ed64b3]
    2798    22B4    05/30    07:16:02.507    16    ActiveJob.cs(831)            NORMAL     Begin new execution batch at task:(True)-a5e0105b-d4eb-478f-a298-258a3f830d66
    2798    22B4    05/30    07:16:02.507    16    ActiveJob.cs(851)            NORMAL     Dispatching task for execution:True-a5e0105b-d4eb-478f-a298-258a3f830d66
    2798    2978    05/30    07:16:02.507    16    ActiveJob.cs(581)            NORMAL     Begin ExecuteTask:JobID=e043f99c-13ab-45ba-92d2-245498ed64b3, ItemID=a5e0105b-d4eb-478f-a298-258a3f830d66
    2798    2978    05/30    07:16:02.507    01    TaskExecutor.cs(692)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Setting up Fsm: verb[85d11aaa-bbbc-427d-9932-eeb3fd4759f5]
    2798    2978    05/30    07:16:02.507    01    TaskExecutor.cs(487)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    ExecuteTask(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Starting task instance
    2798    22E8    05/30    07:16:02.523    03    timer.cpp(490)            ACTIVITY    CTimerMgr::TimerThread
    2798    22E8    05/30    07:16:02.523    03    timer.cpp(503)    [000000001F7C9B38]        ACTIVITY    CTimerMgr::TimerThreadInternal
    2798    11C4    05/30    07:16:02.523    02    EventManager.cs(98)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Publishing event from TaskInstance.cs(411): TaskStart, [TaskID=a5e0105b-d4eb-478f-a298-258a3f830d66]
    2798    11C4    05/30    07:16:02.538    01    TaskInstance.cs(447)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Task: Initial transition enqueued, startState='ConfigureProtection.StartState'
    2798    2978    05/30    07:16:02.538    27    FindPrincipalServerBlock.cs(268)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Found Principal server for DatasourceId = 40794e40-6319-4498-88de-ebc21b659848 Server= titan.contoso.com
    2798    22B4    05/30    07:16:02.773    27    ConfigureProtectionMachine.cs(581)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    WriterHelper.OnConfigureDeltaTrackingSuccess succeeded for datasource 40794e40-6319-4498-88de-ebc21b659848
    2798    22E8    05/30    07:16:02.820    03    timer.cpp(513)    [000000001F7C9B38]        ACTIVITY    Shutting down timer thread.
    2798    18C4    05/30    07:16:02.820    02    EventManager.cs(98)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Publishing event from TaskInstance.cs(828): TaskStop, [TaskID=a5e0105b-d4eb-478f-a298-258a3f830d66]
    2798    18C4    05/30    07:16:02.820    01    TaskExecutor.cs(849)        A5E0105B-D4EB-478F-A298-258A3F830D66    NORMAL    Task stopped (state=Completed, result=Success; 0; None)
    2798    18C4    05/30    07:16:02.820    16    Task.cs(235)            NORMAL     Changing task state from 'GenerateWorkplan' -> 'Execute' (a5e0105b-d4eb-478f-a298-258a3f830d66)
    2798    18C4    05/30    07:16:02.820    16    ActiveJob.cs(831)            NORMAL     Begin new execution batch at task:(True)-5d30018e-df77-456a-9074-f64e343d9a2f
    2798    18C4    05/30    07:16:02.820    16    ActiveJob.cs(851)            NORMAL     Dispatching task for execution:True-5d30018e-df77-456a-9074-f64e343d9a2f
    2798    18C4    05/30    07:16:02.820    16    ActiveJob.cs(581)            NORMAL     Begin ExecuteTask:JobID=e043f99c-13ab-45ba-92d2-245498ed64b3, ItemID=5d30018e-df77-456a-9074-f64e343d9a2f
    2798    18C4    05/30    07:16:02.835    27    DatasourceServerTypeLock.cs(406)            NORMAL    Server 1b26c505-eb21-4b6d-994b-45479b364686 is not already registed to Acquire a lock, Registering the server now for the task 5d30018e-df77-456a-9074-f64e343d9a2f, IsDatasoureServerTypeLockNeeded = False
    2798    18C4    05/30    07:16:02.835    01    DPMTaskController.cs(70)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    (job=e043f99c-13ab-45ba-92d2-245498ed64b3, taskId=5d30018e-df77-456a-9074-f64e343d9a2f) DPMTaskControllerHelper : ExecuteTask - CheckTaskStatus returned ReadyToExecute
    2798    18C4    05/30    07:16:02.835    01    TaskExecutor.cs(692)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Setting up Fsm: verb[c4cae2f7-f068-4a37-914e-9f02991868da]
    2798    18C4    05/30    07:16:02.835    27    CommonLoop.cs(344)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    DatamovePollingCmdTimeoutInMin = 30
    2798    18C4    05/30    07:16:02.835    01    TaskExecutor.cs(487)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    ExecuteTask(job=e043f99c-13ab-45ba-92d2-245498ed64b3) - Starting task instance
    2798    279C    05/30    07:16:02.835    03    timer.cpp(490)            ACTIVITY    CTimerMgr::TimerThread
    2798    279C    05/30    07:16:02.835    03    timer.cpp(503)    [000000001F71C128]        ACTIVITY    CTimerMgr::TimerThreadInternal
    2798    11C4    05/30    07:16:02.835    02    EventManager.cs(98)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Publishing event from TaskInstance.cs(411): TaskStart, [TaskID=5d30018e-df77-456a-9074-f64e343d9a2f]
    2798    11C4    05/30    07:16:02.867    01    TaskInstance.cs(447)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Task: Initial transition enqueued, startState='Backup.StartState'
    2798    11C4    05/30    07:16:02.867    27    BackupMachine.cs(2308)        5D30018E-DF77-456A-9074-F64E343D9A2F    ACTIVITY    BackupMachine : Starting machine execution
    2798    11C4    05/30    07:16:02.882    27    DecideConsistencyCheckNeededBlock.cs(126)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Consistency Check (Needed) for datasource=40794e40-6319-4498-88de-ebc21b659848
    2798    11C4    05/30    07:16:02.882    27    FindPrincipalServerBlock.cs(268)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Found Principal server for DatasourceId = 40794e40-6319-4498-88de-ebc21b659848 Server= titan.contoso.com
    2798    11C4    05/30    07:16:02.898    27    DatasourceServerTypeLock.cs(406)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Server 1b26c505-eb21-4b6d-994b-45479b364686 is not already registed to Acquire a lock, Registering the server now for the task 5d30018e-df77-456a-9074-f64e343d9a2f, IsDatasoureServerTypeLockNeeded = False
    2798    11C4    05/30    07:16:02.898    27    OperationTypeLock.cs(583)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    In LockServer() of ReplicationOperationTypeLock, returning lockStatus = AcquiredLock
    2798    11C4    05/30    07:16:02.898    02    EventManager.cs(98)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Publishing event from Replica.cs(2432): ReplicaStatusChange, [DataSourceID=503bb0bc-7f3d-4eec-be64-b155ed22d8b8]
    2798    11C4    05/30    07:16:02.898    27    OperationTypeLock.cs(488)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    In Lock() of ReplicationOperationTypeLock, returning lockStatus = AcquiredLock
    2798    11C4    05/30    07:16:02.913    23    ServerAlert.cs(937)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    AHP: DecrementRepeatCount() called for alert (AlertId=[281f7073-0c0d-4de1-80af-d2f8885cd46e], AlertMapId=[7d69564f-243d-4f37-94b7-32d5966c5808]
    2798    11C4    05/30    07:16:02.913    23    AlertDetails.cs(428)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    DecrementRepeatCount: Decrementing repeat count for alertMapId:7d69564f-243d-4f37-94b7-32d5966c5808
    2798    11C4    05/30    07:16:02.913    23    ServerAlert.cs(2087)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    AHP: Populating the backup time spans for alert with alert ID:[281f7073-0c0d-4de1-80af-d2f8885cd46e] and alert map ID:[7d69564f-243d-4f37-94b7-32d5966c5808]
    2798    11C4    05/30    07:16:02.913    02    EventManager.cs(98)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    Publishing event from ServerAlert.cs(972): AlertStateChange, [ObjectId=40794e40-6319-4498-88de-ebc21b659848]
    2798    11C4    05/30    07:16:02.913    23    AlertVisibility.cs(267)        5D30018E-DF77-456A-9074-F64E343D9A2F    NORMAL    StopAutoHealActionTimer: Timer for alertId=[281f7073-0c0d-4de1-80af-d2f8885cd46e] not found
    2798    11C4    05/30    07:16:02.913    23    ServerAlert.cs(1962)        5D30018E-DF77-456A-907
    Thursday, May 30, 2019 8:35 AM
  • Here is some of the logs from the server being backed up


    1880 21A8 06/03 13:28:26.883 31 vssbaserequestor.cpp(51) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssBaseRequestor: constructor [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:26.883 31 vsssnapshotrequestor.cpp(104) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:26.883 31 vssbaserequestor.cpp(88) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssBaseRequestor::Initialize [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:26.914 31 vsssnapshotrequestor.cpp(205) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::InitializeSnapshotCreation [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.102 31 vsssnapshotrequestor.cpp(658) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::SetContext [0000015CB25EF7A0] m_snapshotInfo.snapshotContext 16
    1880 21A8 06/03 13:28:27.102 03 miscellaneousutils.cpp(1081) AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL Error:ERROR_UNKNOWN_PRODUCT, While detecting DPM version. Assuming DPM isnt installed.
    1880 21A8 06/03 13:28:27.102 31 vsssnapshotrequestor.cpp(409) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::AddVolumeForSnapshot [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.133 31 vsssnapshotrequestor.cpp(441) AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL ssLocalVolumeGuid = [\\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}\], ssClusterVolGuid=[\\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}\]
    1880 21A8 06/03 13:28:27.133 31 vsssnapshotrequestor.cpp(477) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::AddVolumeForSnapshot [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.133 31 vsssnapshotrequestor.cpp(500) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor: AddVolumeForSnapshot - Marked volume \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}\ to be snapshot
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(32) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournalHelper::ActivateJournal Volume Path = \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}\, max size = 0x000000001F400000, alloc delta = 0x0000000003200000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(527) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(545) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}, Volume Handle = a38
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(123) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL UsnJournalID    = 0x01D4B2A2489AE17A
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(124) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL FirstUsn        = 0x0000000000000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(125) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL NextUsn         = 0x000000001962A738
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(126) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL LowestValidUsn  = 0x0000000000000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(127) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL MaxUsn          = 0x7FFFFFFFFFFF0000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(128) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL MaximumSize     = 0x0000000100000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(129) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL AllocationDelta = 0x0000000040000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(159) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL Need to reset USN false
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(527) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(545) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournal::GetVolumeHandle Volume Path = \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}, Volume Handle = a38
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(466) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CUsnJournalHelper::GetNextUsnInternal(vol:a38)
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(488) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL UsnJournalID    = 0x01D4B2A2489AE17A
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(489) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL FirstUsn        = 0x0000000000000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(490) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL NextUsn         = 0x000000001962A738
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(491) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL LowestValidUsn  = 0x0000000000000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(492) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL MaxUsn          = 0x7FFFFFFFFFFF0000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(493) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL MaximumSize     = 0x0000000100000000
    1880 21A8 06/03 13:28:27.149 18 usnjournalhelper.cpp(494) [0000003AE347EE70] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL AllocationDelta = 0x0000000040000000
    1880 21A8 06/03 13:28:27.211 31 filterwrapper.cpp(48) [0000003AE347EDB0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL Loaded DPMFSFilterWrapperDLL.dll
    1880 21A8 06/03 13:28:27.227 03 cconfiguredeltasubtask.cpp(586) [0000015CB2439B90] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL Hr: = [0xe0062000] Reinitializing Tracking on Volume \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}\ as Tracking is in failed state.
    1880 21A8 06/03 13:28:27.227 31 filtercommandhandler.cpp(281) [0000015CB162DAF0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CleanupTracking on Volume \\?\Volume{e230fb99-a506-4753-b2c6-26f303230ca8}
    1880 21A8 06/03 13:28:27.227 31 filtercommandhandler.cpp(448) [0000015CB162DAF0] AA20F1FF-CE11-4C11-B01C-20148237F6AE WARNING Failed: Hr: = [0xe0062000] : DeviceIoControl call failed with [0xb242f160] for IoCtl: 14614600
    1880 21A8 06/03 13:28:27.227 31 filtercommandhandler.cpp(387) [0000015CB162DAF0] AA20F1FF-CE11-4C11-B01C-20148237F6AE WARNING Failed: Hr: = [0xe0062000] : Encountered Failure: : lVal : DevIoCtl(( ((((ULONG)0xDF)) << 16) | ((0) << 14) | ((0x12) << 2) | (0) ), 0, 0, (PBYTE)&output, sizeof(output))
    1880 21A8 06/03 13:28:27.227 31 filterwrapper.cpp(826) [0000015CB25EB9C0] AA20F1FF-CE11-4C11-B01C-20148237F6AE WARNING Failed: Hr: = [0xe0062000] : Encountered Failure: : lVal : m_pFilter->GetSessionInfo(pActiveBitmapId, &entries, &storesize, &frozenBitmapId)
    1880 21A8 06/03 13:28:27.289 31 vsssnapshotrequestor.cpp(122) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.289 31 vsssnapshotrequestor.cpp(2182) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::CleanUp [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.289 31 vsssnapshotrequestor.cpp(1768) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssSnapshotRequestor::ReleaseVolumesForSnapshot [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.289 31 vssbaserequestor.cpp(69) [0000015CB25EF7A0] AA20F1FF-CE11-4C11-B01C-20148237F6AE NORMAL CVssBaseRequestor: destructor [0000015CB25EF7A0]
    1880 21A8 06/03 13:28:27.289 03 cworkitem.cpp(23) [0000015CB0753820] AA20F1FF-CE11-4C11-B01C-20148237F6AE ACTIVITY WorkItem stopping
    1880 21A8 06/03 13:28:27.604 03 cworkitem.cpp(429) [0000015CB0753518] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY Idle Timer created with timeout = 390000
    1880 21A8 06/03 13:28:27.620 03 cbackupworkitem.cpp(448) [0000015CB07534A0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL Processing app server account name [domain\Server001]
    1880 21A8 06/03 13:28:27.636 03 cbackupworkitem.cpp(448) [0000015CB07534A0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL Processing app server account name [domain\Server002]
    1880 21A8 06/03 13:28:27.651 03 cworkitem.cpp(23) [0000015CB07534A0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY WorkItem stopping
    1880 21A8 06/03 13:28:27.745 31 vssbaserequestor.cpp(51) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssBaseRequestor: constructor [0000015CB245E6E8]
    1880 21A8 06/03 13:28:27.745 31 vsssnapshotrequestor.cpp(104) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000015CB245E6E8]
    1880 21A8 06/03 13:28:27.745 03 cworkitem.cpp(429) [0000015CB0753438] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY Idle Timer created with timeout = 390000
    1880 21A8 06/03 13:28:27.745 61 vainquirysubtask.cpp(215) [0000015CB245E390] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL Writer metadata not needed for inquiry.
    1880 21A8 06/03 13:28:27.745 61 inquirysubtask.cpp(1030) [0000015CB245E390] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL ==>Tasks::CInquirySubTask::ExecuteInquiry
    1880 21A8 06/03 13:28:27.745 61 necluster.cpp(84) [0000015CB25EB2D0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL ==>CNECluster::EnumerateClusterDetails
    1880 21A8 06/03 13:28:27.776 61 necluster.cpp(84) [0000015CB25EB2D0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL <--CNECluster::EnumerateClusterDetails
    1880 21A8 06/03 13:28:27.776 61 inquirysubtask.cpp(1030) [0000015CB245E390] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL <--Tasks::CInquirySubTask::ExecuteInquiry
    1880 1718 06/03 13:28:27.776 61 inquirysubtask.cpp(457) [0000015CB245E390] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL Sending final response with 2 records
    1880 1718 06/03 13:28:27.792 61 inquirysubtask.cpp(989) [0000015CB245E390] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CInquirySubTask::Inquiry finished with status [0000000000]
    1880 1718 06/03 13:28:27.792 31 vsssnapshotrequestor.cpp(122) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [0000015CB245E6E8]
    1880 1718 06/03 13:28:27.792 31 vsssnapshotrequestor.cpp(2182) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssSnapshotRequestor::CleanUp [0000015CB245E6E8]
    1880 1718 06/03 13:28:27.792 31 vsssnapshotrequestor.cpp(1768) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssSnapshotRequestor::ReleaseVolumesForSnapshot [0000015CB245E6E8]
    1880 1718 06/03 13:28:27.792 31 vssbaserequestor.cpp(69) [0000015CB245E6E8] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 NORMAL CVssBaseRequestor: destructor [0000015CB245E6E8]
    1880 1718 06/03 13:28:27.792 03 cworkitem.cpp(23) [0000015CB07533C0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY WorkItem stopping
    1880 1718 06/03 13:28:27.870 03 cworkitem.cpp(429) [0000015CB0753B38] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY Idle Timer created with timeout = 390000
    1880 21A8 06/03 13:28:52.177 03 cworkitem.cpp(23) [0000015CB0753AC0] 37FA37B9-2090-4EBE-A43B-CC6CF324BB45 ACTIVITY WorkItem stopping
    1880 1AA0 06/03 13:28:52.521 03 service.cpp(147) [0000003AE252FB70] ACTIVITY CService::ServiceHandlerExInternal
    1880 1AA0 06/03 13:28:52.536 03 service.cpp(147) [0000003AE252FB70] ACTIVITY CService::ServiceHandlerExInternal
    1880 1AA0 06/03 13:29:52.756 03 service.cpp(147) [0000003AE252FB70] ACTIVITY CService::ServiceHandlerExInternal
    1880 1AA0 06/03 13:29:52.756 03 service.cpp(147) [0000003AE252FB70] ACTIVITY CService::ServiceHandlerExInternal
    1880 21A8 06/03 13:30:03.004 03 cworkitem.cpp(429) [0000015CB07536D8] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD ACTIVITY Idle Timer created with timeout = 390000
    1880 21A8 06/03 13:30:03.020 29 radefaultsubtask.cpp(248) [0000015CB162CA60] 67D9FB9C-7465-4297-9F89-A6FD57666219 ACTIVITY CMTADefaultSubTask::CommandReceivedSpecific => Command RefreshConnectivity Received
    1880 1718 06/03 13:30:03.036 03 cbackupworkitem.cpp(448) [0000015CB0753660] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL Processing app server account name [domain\Server001]
    1880 047C 06/03 13:30:03.036 05 genericstatus.cpp(981) NORMAL CallUpdateQfesInstalledRegKey called in worker thread
    1880 047C 06/03 13:30:03.036 05 genericstatus.cpp(1532) NORMAL Windows Qfe KB no: [KB948465] is not applicable on this machine
    1880 047C 06/03 13:30:03.036 05 genericstatus.cpp(1532) NORMAL Windows Qfe KB no: [KB971394] is not applicable on this machine
    1880 21A8 06/03 13:30:03.036 05 genericstatus.cpp(1327) [0000015CB0744CA0] 67D9FB9C-7465-4297-9F89-A6FD57666219 NORMAL Wait for CallUpdateQfesInstalledRegKey succeeded. Returning m_QfesInstalled = 31
    1880 21A8 06/03 13:30:03.036 03 schannelutils.cpp(129) 67D9FB9C-7465-4297-9F89-A6FD57666219 WARNING Failed: Hr: = [0x80070002] : Unable to open RegKey [HKLM\Software\Microsoft\Microsoft Data Protection Manager\Agent\2.0\Certificates\Server001.domain]
    1880 21A8 06/03 13:30:03.036 05 genericstatus.cpp(1733) [0000015CB0744CA0] 67D9FB9C-7465-4297-9F89-A6FD57666219 NORMAL majorVerNum[10], minorVerNum[19], buildNum[58], hotfixNum[0]
    1880 21A8 06/03 13:30:03.036 31 vssbaserequestor.cpp(51) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssBaseRequestor: constructor [0000015CB2464228]
    1880 21A8 06/03 13:30:03.036 31 vsssnapshotrequestor.cpp(104) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000015CB2464228]
    1880 21A8 06/03 13:30:03.036 03 cworkitem.cpp(429) [0000015CB0753CF8] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C ACTIVITY Idle Timer created with timeout = 390000
    1880 21A8 06/03 13:30:03.051 61 vainquirysubtask.cpp(215) [0000015CB2463ED0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL Writer metadata not needed for inquiry.
    1880 21A8 06/03 13:30:03.051 61 inquirysubtask.cpp(1030) [0000015CB2463ED0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL ==>Tasks::CInquirySubTask::ExecuteInquiry
    1880 21A8 06/03 13:30:03.051 61 necluster.cpp(84) [0000015CB25EC4A0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL ==>CNECluster::EnumerateClusterDetails
    1880 21A8 06/03 13:30:03.098 61 necluster.cpp(84) [0000015CB25EC4A0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL <--CNECluster::EnumerateClusterDetails
    1880 21A8 06/03 13:30:03.098 61 inquirysubtask.cpp(1030) [0000015CB2463ED0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL <--Tasks::CInquirySubTask::ExecuteInquiry
    1880 1454 06/03 13:30:03.098 61 inquirysubtask.cpp(457) [0000015CB2463ED0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL Sending final response with 2 records
    1880 1718 06/03 13:30:03.098 03 cbackupworkitem.cpp(448) [0000015CB0753660] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL Processing app server account name [domain\Server002]
    1880 1454 06/03 13:30:03.098 61 inquirysubtask.cpp(989) [0000015CB2463ED0] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CInquirySubTask::Inquiry finished with status [0000000000]
    1880 175C 06/03 13:30:03.114 31 vsssnapshotrequestor.cpp(122) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssSnapshotRequestor::~CVssSnapshotRequestor [0000015CB2464228]
    1880 175C 06/03 13:30:03.114 31 vsssnapshotrequestor.cpp(2182) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssSnapshotRequestor::CleanUp [0000015CB2464228]
    1880 175C 06/03 13:30:03.114 31 vsssnapshotrequestor.cpp(1768) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssSnapshotRequestor::ReleaseVolumesForSnapshot [0000015CB2464228]
    1880 175C 06/03 13:30:03.114 31 vssbaserequestor.cpp(69) [0000015CB2464228] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C NORMAL CVssBaseRequestor: destructor [0000015CB2464228]
    1880 175C 06/03 13:30:03.114 03 cworkitem.cpp(23) [0000015CB0753C80] 31F8FE8C-FCFA-4F5D-B6B9-97E1A4467E4C ACTIVITY WorkItem stopping
    1880 1718 06/03 13:30:03.129 03 cworkitem.cpp(23) [0000015CB0753660] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD ACTIVITY WorkItem stopping
    1880 1718 06/03 13:30:03.348 31 vssbaserequestor.cpp(51) [0000015CB245F498] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL CVssBaseRequestor: constructor [0000015CB245F498]
    1880 1718 06/03 13:30:03.348 31 vsssnapshotrequestor.cpp(104) [0000015CB245F498] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL CVssSnapshotRequestor::CVssSnapshotRequestor [0000015CB245F498]
    1880 1718 06/03 13:30:03.348 03 cworkitem.cpp(429) [0000015CB07537B8] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD ACTIVITY Idle Timer created with timeout = 390000
    1880 1718 06/03 13:30:03.348 61 vainquirysubtask.cpp(215) [0000015CB245F140] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL Writer metadata not needed for inquiry.
    1880 1718 06/03 13:30:03.348 61 inquirysubtask.cpp(1030) [0000015CB245F140] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL ==>Tasks::CInquirySubTask::ExecuteInquiry
    1880 1718 06/03 13:30:03.348 61 necluster.cpp(84) [0000015CB25EB2A0] 834872B1-B9BC-4EF7-8784-DCE0BBC590BD NORMAL ==

    Monday, June 3, 2019 1:52 PM
  • The logs don't tell much I'm afraid, since there are already three different people in this thread with the same issue I suggest creating a case directly to Microsoft about this issue.

    For the community's sake, it would be great if you could report back of your findings!


    Blog: https://thesystemcenterblog.com LinkedIn:

    Monday, June 3, 2019 10:18 PM
  • Just wanted to check back in and let everyone know I ended up opening a case with Microsoft, and they were able to repair the replica on the DPM server. Since thing all our jobs have been running smoothly.

    Leon thank you for trying to get to the bottom of the problem.

    • Marked as answer by kstate CU IT Sunday, June 9, 2019 5:57 PM
    Sunday, June 9, 2019 5:57 PM
  • Thanks for the update, so the issue was with the replica itself? Just to get a clear picture of the resolution :-)

    Blog: https://thesystemcenterblog.com LinkedIn:

    Monday, June 10, 2019 6:11 AM
  • its possible to get the solution from you? or we need the MS team for solution?

    Monday, June 10, 2019 8:55 PM
  • kstate CU IT

    could you please tell us more about the solution!!

    thx

    Thursday, June 13, 2019 6:51 AM
  • Hi,

    I am having the same issue on my DPM 2019 and Server 2019 installation, can you please provide some info on how MS were able to fix the issue?

    thanks in advance

    Wednesday, July 3, 2019 5:25 AM
  • hi,

    i have an open case with MS since 1 week. they didnt not find a solution ...but we are working every day...

    regards

    Wednesday, July 3, 2019 7:33 AM