locked
DPM 2012 R2 - Azure Backups fail. RRS feed

  • Question

  • I am running Windows Server 2012 R2, System Center 2012 R2 - Data Protection Manager and every time I run a DPM job with online backup it errors.  Here are a few errors from the Operational LOG in: %programfiles%\Windows Azure Backup Agent\Temp folder.

    3160 1504 12/29 20:56:09.123 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 21:02:16.728 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=12:13:28.3499950. Number of running jobs=0
    3160 2EB4 12/29 21:11:07.770 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 21:11:15.832 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 21:12:16.722 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=12:23:28.3438310. Number of running jobs=0
    3160 2EC8 12/29 21:22:16.716 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=12:33:28.3377049. Number of running jobs=0
    3160 2EB4 12/29 21:26:14.526 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 21:26:22.589 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 21:32:16.710 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=12:43:28.3315048. Number of running jobs=0
    3160 2EB4 12/29 21:41:21.283 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 21:41:29.173 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 21:42:16.704 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=12:53:28.3253950. Number of running jobs=0
    3160 2EC8 12/29 21:52:16.698 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:03:28.3192181. Number of running jobs=0
    3160 2EB4 12/29 21:56:27.961 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 21:56:35.867 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 22:02:16.692 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:13:28.3130613. Number of running jobs=0
    3160 2EB4 12/29 22:11:34.780 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 22:11:42.623 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 22:12:16.685 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:23:28.3069219. Number of running jobs=0
    3160 2EC8 12/29 22:22:16.679 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:33:28.3007382. Number of running jobs=0
    3160 2EB4 12/29 22:26:41.551 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 22:26:49.411 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 22:32:16.673 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:43:28.2946052. Number of running jobs=0
    3160 2EB4 12/29 22:41:48.402 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 22:41:56.183 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 22:42:16.667 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=13:53:28.2884185. Number of running jobs=0
    3160 2EC8 12/29 22:52:16.661 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:03:28.2823011. Number of running jobs=0
    3160 2EB4 12/29 22:56:55.158 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 22:57:03.017 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 23:02:16.655 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:13:28.2761078. Number of running jobs=0
    3160 2EB4 12/29 23:12:01.867 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 23:12:09.805 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 23:12:16.648 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:23:28.2699404. Number of running jobs=0
    3160 2EC8 12/29 23:22:16.642 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:33:28.2637623. Number of running jobs=0
    3160 2EB4 12/29 23:27:08.530 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 1504 12/29 23:27:16.592 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 23:32:16.636 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:43:28.2576017. Number of running jobs=0
    3160 2EB4 12/29 23:42:15.286 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]
    3160 2EC8 12/29 23:42:16.630 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=14:53:28.2514623. Number of running jobs=0
    3160 1504 12/29 23:42:23.333 22 genericthreadpool.cpp(823) [000000001B2D9318]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[50]
    3160 2EC8 12/29 23:52:16.624 71 CBEngineServiceHost.cs(464)  ACD5A900-4296-43D7-A2CD-51DE599CD332 NORMAL Engine will not shutdown now. Time elapsed since last activity=15:03:28.2453040. Number of running jobs=0
    3160 2EB4 12/29 23:57:22.058 22 genericthreadpool.cpp(823) [000000001B2EB070]  NORMAL Hr: = [0x80070002] CGenericThreadPool::m_dwMaximumNumberOfThreads[256]

    Also I look in the system log and see 'Disk 2 has been surprise removed.' Error 157. That error shows up every time a online recovery point runs. Not sure what is going on.

    Thanks for taking a look.

    Nick

    Monday, December 30, 2013 12:07 AM

Answers

  • Hi,

    It looks to me that Symantec may automatically protect new volumes as they are created, and DPM tries to delete the DB file from the backup .VHD but cannot.  Is there a way to configure Symantec Endpoint Protection so it does not automatically attach itself to new volumes so the DB never gets created ?


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    • Marked as answer by Turbostud1 Tuesday, December 31, 2013 12:41 AM
    Monday, December 30, 2013 11:11 PM

All replies

  • Hi,

    I don't think those log snippets covers the time of the error, looks like last activity was 15 hrs. earlier.

    Please repro the problem again, then right after the failure, zip up all the logs under the %programfiles%\Windows Azure Backup Agent\Temp folder and send them to:  waobsupport@microsoft.com

    Please include this threads URL in the mail so we know what problem to post back to.


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    Monday, December 30, 2013 1:44 AM
  • Sent it to waobsupport@microsoft.com. Thanks for your time on this.

    Nick

    Monday, December 30, 2013 7:29 PM
  • Hi Nick,

    I just received them - thanks.


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    Monday, December 30, 2013 7:34 PM
  • Hi Nick,

    The best I can tell this is caused by Symantec endpoint protection having System Volume Information\EfaData\SYMEFA.DB locked on the a volume we create during.

    <CBEngine0.errlog>
    3160 6F20 12/30 18:54:33.158 75 CBDataSource.cs(684)  AEA08301-8129-4F8B-B5C9-154A6AA1A20E NORMAL Starting backup job with jobId: d45ef5eb-61ef-4eac-992e-c0e87f953657
    3160 68D4 12/30 18:54:33.377 71 async.cpp(892)  D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL Hr: = [0x00000000] QueryTaskId success!.
    3160 68D4 12/30 18:54:33.377 71 backupasync.cpp(989) [000000001F8FE710] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL ==>CBpBackupAsync::DoAsyncOperation
    3160 68D4 12/30 18:54:33.377 71 backupasync.cpp(999) [000000001F8FE710] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL ==>CBpBackupAsync::DoBackup
    ..
    ..
    .
    3160 68D4 12/30 18:54:47.268 18 fixupreaderiterator.cpp(175) [0000000022F23CB0] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL CFixupReaderIterator::SetFileSystemFlags (0x0) called
    3160 68D4 12/30 18:54:47.268 18 pruningiterator.cpp(479) [0000000022EC15C0] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL CPruningIterator::GetNextFile - File [\\?\Volume{55b8563f-6eac-11e3-80c3-005056a355ee}\System Volume Information\EfaData\SYMEFA.DB] returned for deletion
    3160 68D4 12/30 18:54:47.268 18 fswrapper.cpp(932) [000000001E64E730] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Parameter: [0x80070020], FilePath = \\?\Volume{55b8563f-6eac-11e3-80c3-005056a355ee}\System Volume Information\EfaData\SYMEFA.DB
    3160 68D4 12/30 18:54:47.268 18 fswrapper.cpp(932) [000000001E64E730] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Failed: Hr: = [0x80070020] : CreateFile failed \\?\Volume{55b8563f-6eac-11e3-80c3-005056a355ee}\System Volume Information\EfaData\SYMEFA.DB with error :32
    3160 68D4 12/30 18:54:47.268 70 onlinesubtask.cpp(496) [000000001F142180] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Failed: Hr: = [0x80070020] COnlineSubTask::UpdateStatus => hr
    3160 68D4 12/30 18:54:47.268 71 dscontext.cpp(152) [0000000022A3B160] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Last completed state for Ds Id (1125970277527081389) is 18
    3160 68D4 12/30 18:54:47.268 71 dscontext.cpp(158) [0000000022A3B160] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Ds Id (1125970277527081389) failed. DLS: 0 HRESULT: 0x80070020
    3160 68D4 12/30 18:54:47.268 71 replicator.cpp(315) [000000001F80A650] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Failed: Hr: = [0x80070020] SetupReplicationForReplica unsuccessful for replica id ({9139E575-A0BF-418C-B0B9-44829EE71E30}) Volume (\\?\Volume{a03f2ff4-5e08-11e3-80bf-005056a355ee}\))
    3160 68D4 12/30 18:54:47.268 71 asyncworker.cpp(230) [000000001F8FE718] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL <--CBpAsyncWorker::DoWork
    ...
    ..
    .
    3160 68D4 12/30 18:54:47.486 71 backupasync.cpp(1023) [000000001F8FE710] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL Backup Progress: Data transfer finished
    3160 68D4 12/30 18:54:47.486 71 backupasync.cpp(1045) [000000001F8FE710] D45EF5EB-61EF-4EAC-992E-C0E87F953657 WARNING Failed: Hr: = [0x80070020] Backup Progress: Failed
    3160 68D4 12/30 18:54:47.486 71 backupasync.cpp(1048) [000000001F8FE710] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL Backup Progress: UnInitialize Storage started.
    3160 68D4 12/30 18:54:47.486 32 fileprovider.cpp(915) [000000001F156190] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL ==>FileProvider::Uninitialize
    3160 68D4 12/30 18:54:47.486 32 fileprovider.cpp(1732) [000000001F156190] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL ==>FileProvider::DismountVolume
    3160 68D4 12/30 18:54:47.502 32 fileprovider.cpp(1769) [000000001F156190] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL FileProvider::DismountVolume DismountVolume on \\?\Volume{55b8563f-6eac-11e3-80c3-005056a355ee} Complete
    3160 68D4 12/30 18:54:47.502 32 fileprovider.cpp(1732) [000000001F156190] D45EF5EB-61EF-4EAC-992E-C0E87F953657 NORMAL <--FileProvider::DismountVolume
    >snip<

    Seem to be a known issue and has a solution from Symantec.

    Windows Backup fails after installing Symantec Endpoint Protection 12.1
    http://www.symantec.com/business/support/index?page=content&id=TECH168402

    Cause
    =====
    The SEP client utilizes a Extended File Attribute (EFA) database stored on the \System Volume Information directory. Windows Server Backup attempts to access the SEP client's EFA database during the backup process fail as this file is locked.

    Solution
    =======
    This problem is fixed in Symantec Endpoint Protection (SEP) 12.1 Release Update 2 (RU2) Maintenence Patch 1 (MP1).

    Please apply the update and let me know if that resolves it.


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    Monday, December 30, 2013 9:38 PM
  • I am on 12.1 RU4 so not sure what is going on.

    Nick

    Monday, December 30, 2013 10:50 PM
  • Hi,

    It looks to me that Symantec may automatically protect new volumes as they are created, and DPM tries to delete the DB file from the backup .VHD but cannot.  Is there a way to configure Symantec Endpoint Protection so it does not automatically attach itself to new volumes so the DB never gets created ?


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    • Marked as answer by Turbostud1 Tuesday, December 31, 2013 12:41 AM
    Monday, December 30, 2013 11:11 PM
  • Just to try.. I removed Symantec Endpoint Protection from the DPM server and online backups are working. It would be nice to figure out a way to have both Symantec and Online backups on this server.

    Apparently... they broke it again. I'll look to see if I still have 12.1 RU2 to install on it.

    -Nick

    Tuesday, December 31, 2013 12:41 AM
  • Had the same problem. Was Symantec able to offer a resolution at all or were you able to use a different version of SEP and have the backups running at the same time?

    Thanks

    Wednesday, May 7, 2014 5:14 PM
  • Hi,

    We are investigating this issue to see if we can code around the problem.  If this is doable, we will publish a fix in a future agent patch.  In the meantime, unfortunately, the only know workaround is to uninstall the Symantec antivirus software which we know is undesirable.  


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    Friday, September 19, 2014 7:01 AM
  • UPDATE
    =====

    We are  using version 12.1.5 of Symantec Endpoint, which seems to be the latest (released during late September, 2014) and we could not reproduce this problem.  We looked at their release notes. They seem to claim that they addressed an interoperability issue with our Backup product:

    http://www.symantec.com/business/support/index?page=content&id=TECH224706
    Windows Backup of Hyper-V virtual machine fails

    Fix ID: 3234743
    Symptom: Windows Backup of a virtual machine fails on a Hyper-V host. The backup fails with the following error in event viewer

    Application logs:
    Event ID 517: "The backup operation that started has failed with following error code '0x80070020' (The process cannot access the file because it is being used by another process.). Please review the event details for a solution, and then rerun the backup operation once the issue is resolved."
    Solution: Modified the SymEFA.sys driver to handle a scenario where the Microsoft API CreateFile() could fail during backup.

    It seems like they have addressed the issue, can anybody that previously reported this issue please re-test with the version 12.1.5 of Symantec Endpoint and report your findings ? 


    Please remember to click “Mark as Answer” on the post that helps you, and to click “Unmark as Answer” if a marked post does not actually answer your question. This can be beneficial to other community members reading the thread. Regards, Mike J. [MSFT] This posting is provided "AS IS" with no warranties, and confers no rights.

    Monday, November 3, 2014 9:20 PM
  • Guys

    I am having this problem on a Windows 2008 SP2 server. I thought this was a SEP problem too, but i have removed all AV, SEP and other backup software and I still get "Job Failed" in the logging window. I am using the most up to date Agent 2.0.8.707.0. When I look into the engine error log it looks like an issue with the VHD creation. I was wondering have we got any closer to figuring this out please? I really need this to work on 2008 SP2 servers for a client. Please any help would be greatfully received. Thanks.

    Monday, June 22, 2015 7:48 PM