none
Online recovery point creation failed for the following reason: (ID: 3188) Operation failed (ID: 120002) RRS feed

  • Question

  • We are adding Online Protection to Azure for our DPM deployment and receiving the following errors when trying to run the Online Protection jobs for the first time:

    Event Log:

    Log Name:      DPM Alerts
    Source:        DPM-EM
    Date:          1/5/2016 9:43:55 AM
    Event ID:      3188
    Task Category: None
    Level:         Error
    Keywords:      Classic
    User:          N/A
    Computer:      dpmserver.mydomain.com
    Description:

    Creation of online recovery points for E:\ on serverwithagent.mydomain.com have failed. The last online recovery point creation failed for the following reason: (ID: 3188)
    Operation failed. (ID: 120002)
    Event Xml:
    <Event xmlns=(Removed URL)>
      <System>
        <Provider Name="DPM-EM" />
        <EventID Qualifiers="0">3188</EventID>
        <Level>2</Level>
        <Task>0</Task>
        <Keywords>0x80000000000000</Keywords>
        <TimeCreated SystemTime="2016-01-05T16:43:55.000000000Z" />
        <EventRecordID>907</EventRecordID>
        <Channel>DPM Alerts</Channel>
        <Computer>dpmserver.mydomain.com</Computer>
        <Security />
      </System>
      <EventData>
        <Data>
    Creation of online recovery points for E:\ on serverwithagent.mydomain.com have failed. The last online recovery point creation failed for the following reason: (ID: 3188)
    Operation failed. (ID: 120002)</Data>
        <Data>3188</Data>
        <Data>0688333c-e1a7-450a-9bd6-26858d9a52cd</Data>
        <Data>dpmserver.mydomain.com</Data>
        <Data>serverwithagent.mydomain.com</Data>
        <Data>0688333c-e1a7-450a-9bd6-26858d9a52cd</Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>Online recovery point creation failed</Data>
        <Data>0fef88e5-a64e-4559-8c77-f5e493fcf65e</Data>
        <Data>
    Creation of online recovery points for E:\ on serverwithagent.mydomain.com have failed. The last online recovery point creation failed for the following reason: (ID: 3188)
    Operation failed. (ID: 120002)</Data>
        <Data>120002</Data>
        <Data>1</Data>
        <Data>5349</Data>
        <Data>71</Data>
        <Data>FileSystem</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>-1</Data>
        <Data>73e1dd5d-1967-47c9-8dd6-620aafdf79c3</Data>
        <Data>c2a24a44-14f6-4107-9e26-7346f25fad9e</Data>
        <Data>0</Data>
        <Data>
        </Data>
        <Data>Execute resume DPM backups</Data>
        <Data>Online recovery point creation jobs for NO_PARAM E:\ on serverwithagent.mydomain.com have failed 4 times.</Data>
        <Data>CloudBackupFailure</Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>
        </Data>
        <Data>0</Data>
        <Data>Online recovery point creation failed</Data>
        <Data>NoAction</Data>
      </EventData>
    </Event>

    Backup Log:

    054C 29B8 01/05 16:43:55.519 16 ActiveJob.cs(1081)   NORMAL  Changing state of job: 'd2d18913-a541-4266-bfd6-e955c99c6dda' from 'Start' -> 'GenerateWorkplan'
    054C 29B8 01/05 16:43:55.534 02 EventManager.cs(98)   NORMAL Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=d2d18913-a541-4266-bfd6-e955c99c6dda]
    054C 29B8 01/05 16:43:55.534 16 ActiveJob.cs(581)   NORMAL  Begin GenerateWorkplan:JobID=d2d18913-a541-4266-bfd6-e955c99c6dda, ItemID=94dcddaf-1df9-4948-843b-4631178ad4eb
    054C 29B8 01/05 16:43:55.534 01 TaskExecutor.cs(81)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL GenerateWorkplan(job=d2d18913-a541-4266-bfd6-e955c99c6dda) - Entering
    054C 2AD8 01/05 16:43:55.534 02 EventManager.cs(98)   NORMAL Publishing event from ServerAlert.cs(972): AlertStateChange, [ObjectId=0688333c-e1a7-450a-9bd6-26858d9a52cd]
    054C 2AD8 01/05 16:43:55.534 23 AlertVisibility.cs(267)   NORMAL StopAutoHealActionTimer: Timer for alertId=[0fef88e5-a64e-4559-8c77-f5e493fcf65e] not found
    054C 2AD8 01/05 16:43:55.534 23 ServerAlert.cs(1962)   NORMAL UpdateBackupTimeSpans: Populating the backup time spans for alert with alert ID:[0fef88e5-a64e-4559-8c77-f5e493fcf65e]
    054C 29B8 01/05 16:43:55.534 02 EventManager.cs(98)   NORMAL Publishing event from TaskExecutor.cs(107): TaskCreated, [TaskID=94dcddaf-1df9-4948-843b-4631178ad4eb]
    054C 29B8 01/05 16:43:55.550 01 TaskExecutor.cs(127)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL GenerateWorkplan(job=d2d18913-a541-4266-bfd6-e955c99c6dda) - Finished (error=False), executing GenerateWorkplanCallback
    054C 29B8 01/05 16:43:55.550 16 Task.cs(235)   NORMAL  Changing task state from 'Start' -> 'GenerateWorkplan' (94dcddaf-1df9-4948-843b-4631178ad4eb)
    054C 29B8 01/05 16:43:55.550 16 ActiveJob.cs(1081)   NORMAL  Changing state of job: 'd2d18913-a541-4266-bfd6-e955c99c6dda' from 'GenerateWorkplan' -> 'Execute'
    054C 29B8 01/05 16:43:55.550 02 EventManager.cs(98)   NORMAL Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=d2d18913-a541-4266-bfd6-e955c99c6dda]
    054C 29B8 01/05 16:43:55.550 16 ActiveJob.cs(831)   NORMAL  Begin new execution batch at task:(True)-94dcddaf-1df9-4948-843b-4631178ad4eb
    054C 29B8 01/05 16:43:55.566 16 ActiveJob.cs(851)   NORMAL  Dispatching task for execution:True-94dcddaf-1df9-4948-843b-4631178ad4eb
    054C 2E64 01/05 16:43:55.566 16 ActiveJob.cs(581)   NORMAL  Begin ExecuteTask:JobID=d2d18913-a541-4266-bfd6-e955c99c6dda, ItemID=94dcddaf-1df9-4948-843b-4631178ad4eb
    054C 2E64 01/05 16:43:55.566 01 DPMTaskController.cs(70)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL (job=d2d18913-a541-4266-bfd6-e955c99c6dda, taskId=94dcddaf-1df9-4948-843b-4631178ad4eb) DPMTaskControllerHelper : ExecuteTask - CheckTaskStatus returned ReadyToExecute
    054C 2E64 01/05 16:43:55.566 01 TaskExecutor.cs(692)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Setting up Fsm: verb[6e7c76f4-a832-4418-a772-8e58fd7466cb]
    054C 2E64 01/05 16:43:55.566 01 TaskExecutor.cs(487)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL ExecuteTask(job=d2d18913-a541-4266-bfd6-e955c99c6dda) - Starting task instance
    054C 1BC0 01/05 16:43:55.566 03 timer.cpp(490)   ACTIVITY CTimerMgr::TimerThread
    054C 1BC0 01/05 16:43:55.566 03 timer.cpp(503) [00000000194EF888]  ACTIVITY CTimerMgr::TimerThreadInternal
    054C 2E64 01/05 16:43:55.566 02 EventManager.cs(98)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Publishing event from TaskInstance.cs(406): TaskStart, [TaskID=94dcddaf-1df9-4948-843b-4631178ad4eb]
    054C 2E64 01/05 16:43:55.566 01 TaskInstance.cs(442)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Task: Initial transition enqueued, startState='CloudBackupMachine.StartState'
    054C 2E64 01/05 16:43:55.566 27 CloudMachineBase.cs(298)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupMachineFsm Execution Starting...
    054C 2E64 01/05 16:43:57.316 27 CloudBackupMachine.cs(205)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupMachine: Disk Backup Time = 01/05/2016 16:42:31, Cloud Backup Time = 01/01/0001 07:00:00
    054C 2E64 01/05 16:43:57.316 27 CloudBackupMachine.cs(81)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Protected unit guid 5f91d007-e83d-4e75-8f36-388256298a72
    054C 29B8 01/05 16:44:29.363 27 CloudMachineBase.cs(200)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupMachine : inside OnWakeup call, cloud job state = Aborted
    054C 29B8 01/05 16:44:29.363 27 CloudMachineBase.cs(320)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupMachine: inside OnFsmFailureAfterConcurrencyCheck call
    054C 29B8 01/05 16:44:29.379 27 CloudMachineBase.cs(334)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING CloudBackupMachine: FAILURE, errorCode=CloudBackupJobFailed
    054C 29B8 01/05 16:44:29.379 23 ServerAlert.cs(1726)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL AHP: Ignoring to add to alert detail table as alert is not present in AlertTroubleshootingData.xml. AlertEnum:71 and AlertId:3df24df9-e605-4772-8c50-22049644037f
    054C 29B8 01/05 16:44:29.394 02 EventManager.cs(98)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Publishing event from ServerAlert.cs(861): AlertStateChange, [ObjectId=0688333c-e1a7-450a-9bd6-26858d9a52cd]
    054C 29B8 01/05 16:44:29.394 27 CloudUtils.cs(113)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupFailed Alert raised = True for datasource = 0688333c-e1a7-450a-9bd6-26858d9a52cd
    054C 29B8 01/05 16:44:29.394 09 AppAssert.cs(130)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING ASSERT: (FileName:VolumeInformation.cs; LineNumber:415)
    054C 29B8 01/05 16:44:29.394 27 CloudMachineBase.cs(358)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL CloudBackupMachine: Skipping Unlock()
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING Task Diagnostic Information - <?xml version="1.0" encoding="utf-16"?>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING <TaskExecutionContext>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING   <DatasourceId>0688333c-e1a7-450a-9bd6-26858d9a52cd</DatasourceId>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING   <TEVerb>CloudBackup</TEVerb>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING   <TEErrorState>CloudBackupMachine.RunningState</TEErrorState>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING   <TEErrorDetails>&lt;?xml version="1.0" encoding="utf-16"?&gt;
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING &lt;q1:ErrorInfo ErrorCode="120002" DetailedCode="-2147024773" DetailedSource="0" ExceptionDetails="" xmlns:q1(Removed URL) /&gt;</TEErrorDetails>
    054C 29B8 01/05 16:44:29.394 01 TaskInstance.cs(798)  94DCDDAF-1DF9-4948-843B-4631178AD4EB WARNING </TaskExecutionContext>
    054C 1BC0 01/05 16:44:29.410 03 timer.cpp(513) [00000000194EF888]  ACTIVITY Shutting down timer thread.
    054C 29B8 01/05 16:44:29.410 02 EventManager.cs(98)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Publishing event from TaskInstance.cs(823): TaskStop, [TaskID=94dcddaf-1df9-4948-843b-4631178ad4eb]
    054C 29B8 01/05 16:44:29.410 01 TaskExecutor.cs(843)  94DCDDAF-1DF9-4948-843B-4631178AD4EB FATAL Task stopped (state=Failed, error=CloudBackupJobFailed; -2147024773; None), search "Task Diagnostic Information" for details.
    054C 29B8 01/05 16:44:29.410 16 ActiveJob.cs(745)   WARNING  Fail: Task '94dcddaf-1df9-4948-843b-4631178ad4eb' failed with error during execution.
    054C 29B8 01/05 16:44:29.410 16 ActiveJob.cs(523)   NORMAL  Fail job'd2d18913-a541-4266-bfd6-e955c99c6dda' on task'94dcddaf-1df9-4948-843b-4631178ad4eb' at 'ExecuteTask'
    054C 29B8 01/05 16:44:29.410 16 Task.cs(235)   NORMAL  Changing task state from 'GenerateWorkplan' -> 'Execute' (94dcddaf-1df9-4948-843b-4631178ad4eb)
    054C 29B8 01/05 16:44:29.425 16 ActiveJob.cs(424)   NORMAL Cancelling job:'d2d18913-a541-4266-bfd6-e955c99c6dda' due to:'JobFailure'
    054C 29B8 01/05 16:44:29.425 16 ActiveJob.cs(1081)   NORMAL  Changing state of job: 'd2d18913-a541-4266-bfd6-e955c99c6dda' from 'Execute' -> 'Cancel'
    054C 29B8 01/05 16:44:29.441 02 EventManager.cs(98)   NORMAL Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=d2d18913-a541-4266-bfd6-e955c99c6dda]
    054C 29B8 01/05 16:44:29.441 16 ActiveJob.cs(1081)   NORMAL  Changing state of job: 'd2d18913-a541-4266-bfd6-e955c99c6dda' from 'Cancel' -> 'Retire'
    054C 29B8 01/05 16:44:29.441 02 EventManager.cs(98)   NORMAL Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=d2d18913-a541-4266-bfd6-e955c99c6dda]
    054C 29B8 01/05 16:44:29.441 16 Task.cs(235)   NORMAL  Changing task state from 'Execute' -> 'Retire' (94dcddaf-1df9-4948-843b-4631178ad4eb)
    054C 29B8 01/05 16:44:29.441 01 TaskExecutor.cs(179)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL RetireWorkplan(job=d2d18913-a541-4266-bfd6-e955c99c6dda) - Calling derived RetireWorkplan
    054C 29B8 01/05 16:44:29.441 27 TaskExecutorBase.cs(116)  94DCDDAF-1DF9-4948-843B-4631178AD4EB NORMAL Retiring task for (job=d2d18913-a541-4266-bfd6-e955c99c6dda)
    054C 29B8 01/05 16:44:29.441 01 TaskExecutor.cs(225)  94DCDDAF-1DF9-4948-843B-4631178AD4EB ACTIVITY RetireWorkplan(job=d2d18913-a541-4266-bfd6-e955c99c6dda) - Retiring task: Failed
    054C 29B8 01/05 16:44:29.441 16 ActiveJob.cs(1201)   NORMAL  Processing end of job: d2d18913-a541-4266-bfd6-e955c99c6dda
    054C 29B8 01/05 16:44:29.441 68 ActivityWindow.cs(101)   NORMAL  RemoveWait wait : d2d18913-a541-4266-bfd6-e955c99c6dda
    054C 29B8 01/05 16:44:29.441 16 ActiveJob.cs(1224)   NORMAL  Final task state=Retire(94dcddaf-1df9-4948-843b-4631178ad4eb)
    054C 29B8 01/05 16:44:29.441 16 Task.cs(235)   NORMAL  Changing task state from 'Retire' -> 'Failed' (94dcddaf-1df9-4948-843b-4631178ad4eb)
    054C 29B8 01/05 16:44:29.456 16 ActiveJob.cs(1073)   FATAL  Changing state of job: 'd2d18913-a541-4266-bfd6-e955c99c6dda' from 'Retire' -> 'Failed'
    054C 29B8 01/05 16:44:29.456 02 EventManager.cs(98)   NORMAL Publishing event from ActiveJob.cs(1100): JobStateChange, [JobID=d2d18913-a541-4266-bfd6-e955c99c6dda]
    054C 29B8 01/05 16:44:29.456 16 JobManager.cs(741)   NORMAL  Removed job entry from active list:d2d18913-a541-4266-bfd6-e955c99c6dda
    054C 29B8 01/05 16:44:29.456 16 ActiveJob.cs(1297)   NORMAL Completed execution of job:'d2d18913-a541-4266-bfd6-e955c99c6dda', final job state:'Failed'
    054C 2908 01/05 16:44:30.097 09 coreservices.cpp(9541)  5F4E51F9-A226-4B10-BC8C-21C04C0FA698 NORMAL CCoreServices::UpdateAlertVisibilityIfInvisible() entered
    054C 2908 01/05 16:44:30.097 16 engineservices.cpp(419)  5F4E51F9-A226-4B10-BC8C-21C04C0FA698 NORMAL CEngineServices::UpdateAlertVisibilityIfInvisible entered. alertId={3DF24DF9-E605-4772-8C50-22049644037F}, newVisibility=0, invisibilityTimeout=0
    054C 2908 01/05 16:44:30.097 23 ServerAlert.cs(1726)   NORMAL AHP: Ignoring to add to alert detail table as alert is not present in AlertTroubleshootingData.xml. AlertEnum:71 and AlertId:3df24df9-e605-4772-8c50-22049644037f
    054C 2908 01/05 16:44:30.097 02 EventManager.cs(98)   NORMAL Publishing event from ServerAlert.cs(1060): AlertStateChange, [ObjectId=0688333c-e1a7-450a-9bd6-26858d9a52cd]
    054C 2908 01/05 16:44:30.097 23 ServerAlert.cs(1962)   NORMAL UpdateBackupTimeSpans: Populating the backup time spans for alert with alert ID:[3df24df9-e605-4772-8c50-22049644037f]
    054C 12AC 01/05 16:46:09.520 16 JobManager.cs(709)   NORMAL Jobmanager is idle.

    Our deployment:

    DPM 2012 R2 v4.2.1373

    Azure Backup Agent v2.0.9022

    Thank you for your assistance.

    Tuesday, January 5, 2016 5:55 PM