none
DPM 1807 - Hyper-v VM - Replica is Inconsistent - ID 104 - (0x80070079) RRS feed

  • Question

  • Hello:

    I have DPM 1807, and I trying to do backup online for  one Virtual Machine that belong to a Hyper-V Cluster (CSV) with Windows 2012 R2, after the initial configuration and when run the Replica Check, the DPM show this error:

    Description: The replica of Microsoft Hyper-V SERVERXXX on SERVERYYY.MSCSRDS01.domain.com is inconsistent with the protected data source. All protection activities for data source will fail until the replica is synchronized with consistency check. You can recover data from existing recovery points, but new recovery points cannot be created until the replica is consistent. 

    For SharePoint farm, recovery points will continue getting created with the databases that are consistent. To backup inconsistent databases, run a consistency check on the farm. (ID 3106)
    An unexpected error occurred while the job was running. (ID 104 Details: The semaphore timeout period has expired (0x80070079)) 

    DATA:

    - DPM version 1807 running in Windows 2016 (Virtual Machine) using REFS like repository

    - Hyper Cluster - Windows 2012 R2 - Totale nodes : 2  with CSV

    - VM : Windows 2012 R2 with Integration Services installed 

    The VSS writers look fine , both in VM and the Hyper-V Nodes.

    I enabled the VSS debug log (in the VM and the Hyper Nodes ) and DPM debug log  in the DPM's Server. I didn't find any error in the VSS and in the DPM logs I found this:

    Server Side

    - Log File: DPMRACurr:

    1678 040C 11/19 23:09:27.168 03 dmsupport.cpp(228) VERBOSE CDLSRuntime::ProcessCompletionFromDM: DM_COMPLETION_FOR_WRITE
    1678 040C 11/19 23:09:27.168 03 dmsupport.cpp(284) VERBOSE CDLSRuntime::ProcessCompletionFromDM: Going to POST completion pSes=00000165990E2AA0 pST=0000016597121610  pOVL=0000016597121558 pBUFFER=0000000000000000 MsgLen=0xffff7777 dwType=0x2
    1678 040C 11/19 23:09:27.168 03 csubtask.cpp(181) [00000165971212D0] VERBOSE Subtask is busy, completion queued.
    1678 040C 11/19 23:09:27.168 20 session.cpp(885) [00000165990E2AA0] VERBOSE DM: AddMsg Completed but not activating because already have 39 msg in Q, 00000165990E2AA0
    1678 040C 11/19 23:09:27.168 20 session.cpp(895) [00000165990E2AA0] VERBOSE Hr: = [0x00000000] DM: AddMsg Completed SID=2 MID=74 Len=258686 NofMsg=39 pMsg=00000165990DF4E0 pBuf=0000016599088270, 00000165990E2AA0
    1678 040C 11/19 23:09:27.168 03 cworkitem.cpp(236) [00000165970B7B10] VERBOSE ==>Tasks::CAgentWorkItem::ResetIdleTimer
    1678 040C 11/19 23:09:27.168 03 cworkitem.cpp(236) [00000165970B7B10] VERBOSE <--Tasks::CAgentWorkItem::ResetIdleTimer
    1678 0FE4 11/19 23:09:27.168 18 dsmsendersubtaskbase.cpp(261) [00000165971212C0] VERBOSE CDsmSubTaskBase: processing completion (signature:0xaabbcc00 type:0x12, state:1)
    1678 0FE4 11/19 23:09:27.168 18 dsmsendersubtaskbase.cpp(147) [00000165971212C0] VERBOSE CDsmSenderSubTaskBase received write completion in WAIT state
    1678 0FE4 11/19 23:09:27.230 05 genericagent.cpp(373) VERBOSE GenerateChecksum: Computed = 0xADDB510425999286
    1678 0FE4 11/19 23:09:27.230 03 message.cpp(36) [00000165990DF160] VERBOSE DM: CDMMessage::CDMMessage
    1678 0FE4 11/19 23:09:27.230 03 dmsupport.cpp(625) [00000165971258F8] VERBOSE m_pDataMover->SendMessage  pSes=00000165990E2AA0  pST=0000016597121610 pBuf=000001659917D690
    1678 0FE4 11/19 23:09:27.230 20 session.cpp(504) [00000165990E2AA0] VERBOSE ==>CDMSession::ValidateForOperation
    1678 0FE4 11/19 23:09:27.230 20 session.cpp(504) [00000165990E2AA0] VERBOSE <--CDMSession::ValidateForOperation
    1678 0FE4 11/19 23:09:27.230 20 session.cpp(853) [00000165990E2AA0] VERBOSE DM: Message overflowed the queue [40 msg], 00000165990E2AA0
    1678 0FE4 11/19 23:09:27.230 20 session.cpp(885) [00000165990E2AA0] VERBOSE DM: AddMsg Completed but not activating because already have 40 msg in Q, 00000165990E2AA0
    1678 0FE4 11/19 23:09:27.230 20 session.cpp(895) [00000165990E2AA0] VERBOSE Hr: = [0x00000000] DM: AddMsg Completed SID=2 MID=75 Len=258686 NofMsg=40 pMsg=00000165990DF160 pBuf=000001659917D690, 00000165990E2AA0
    1678 0FE4 11/19 23:09:27.230 03 cworkitem.cpp(236) [00000165970B7B10] VERBOSE ==>Tasks::CAgentWorkItem::ResetIdleTimer
    1678 0FE4 11/19 23:09:27.230 03 cworkitem.cpp(236) [00000165970B7B10] VERBOSE <--Tasks::CAgentWorkItem::ResetIdleTimer
    1678 12C8 11/19 23:09:42.399 04 xxcmdproc.cpp(832) [0000016597122DF0] VERBOSE CDLSAgentCommand::CreateInstance
    1678 12C8 11/19 23:09:42.399 04 xxcmdproc.cpp(243) [0000016597122DF0] VERBOSE CDLSAgentCommand::SubmitRequest this:[0000016597122DF0]
    1678 12C8 11/19 23:09:42.399 04 cmdproc.cpp(1063) [0000016598137FD0] VERBOSE CCommandProcessor::OnReceiveRequest
    1678 12C8 11/19 23:09:42.399 04 cmdproc.cpp(3962) [000001659718D630] VERBOSE DCOM Caller authentication passed [bMemberAdmin = 1], [bMemberDPMRADCOMTrustedMachines = 0].
    1678 12C8 11/19 23:09:42.399 04 cmdproc.cpp(3448) [00000165970D7260] VERBOSE ==>CCommandQueue::FindCommand
    1678 12C8 11/19 23:09:42.399 04 cmdproc.cpp(3448) [00000165970D7260] VERBOSE <--CCommandQueue::FindCommand
    1678 12C8 11/19 23:09:42.399 04 cmdproc.cpp(420) [0000016598137FD0] VERBOSE CCommandProcessor::AllocateCommand, ppCommand: 00000063C1CFDB18

    A lines after :

    1678 1894 11/19 23:09:44.634 20 cc_extcalls.cpp(517) [000001659917B310] 678E789A-B867-4E85-8413-A888198B6A7B WARNING DM: TempErr: err=0x40 read=1 write=0
    1678 1894 11/19 23:09:44.634 20 cc_simple.cpp(89) [000001659917B310] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: Aborting  state machine for reason 0 
    1678 1894 11/19 23:09:44.634 20 cc_base.cpp(1226) [000001659917B310] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: Aborting  http state machine for reason 0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(1122) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: : RestoreSessionState: Destination 00000165991602A0 to SERVERYYYY, 00000165991602A0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(1134) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: : RestoreSessionState to:   session: 00000165990E2DC0, sesState: 1, outState: 3, inState: 2, 00000165991602A0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(1168) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: : RestoreSessionState to:   session: 00000165990E2DC0 is NOT RESTARTABLE, 00000165991602A0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(1181) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: Sending error to App for session [00000165990E2DC0], destination: 00000165991602A0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(1187) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: Closing pSes=00000165990E2DC0 becuase of abort
    1678 1894 11/19 23:09:44.634 20 session.cpp(1547) [00000165990E2DC0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE ==>CDMSession::PostCompletionForSessionAction
    1678 1894 11/19 23:09:44.634 20 session.cpp(1560) [00000165990E2DC0] 678E789A-B867-4E85-8413-A888198B6A7B NORMAL Hr: = [0x80070040] DM: Will attempt to post DM_SESSION_ERROR, pSes=00000165990E2DC0 rcv=00000165971211E0 snd=0000000000000000 sesop=0000000000000000 seserr=0000000000000000
    1678 1894 11/19 23:09:44.634 03 dmsupport.cpp(284) 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE CDLSRuntime::ProcessCompletionFromDM: Going to POST completion pSes=00000165990E2DC0 pST=00000165971212A0  pOVL=00000165971211E0 pBUFFER=000001659915D6E0 MsgLen=0xffff7777 dwType=0x40
    1678 1894 11/19 23:09:44.634 03 dmsupport.cpp(294) 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE CDLSRuntime::ProcessCompletionFromDM: Release pSes=00000165990E2DC0 cnt=5 pST=00000165971212A0, 0000016597125820
    1678 1894 11/19 23:09:44.634 20 session.cpp(1547) [00000165990E2DC0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE <--CDMSession::PostCompletionForSessionAction
    1678 1894 11/19 23:09:44.634 20 session.cpp(399) [00000165990E2DC0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: UnbindFromDestination pSes=00000165990E2DC0 pDst=00000165991602A0
    1678 1894 11/19 23:09:44.634 20 destination.cpp(249) 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE RemoveSession (pSession:[0x990e2dc0]) from pDestination:[0x991602a0]
    1678 1894 11/19 23:09:44.634 20 destination.cpp(905) [00000165991602A0] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE DM: CDestination::ConnectionAborted: no need to create a new connection, active connections: 0, r: 0, w: 0, 00000165991602A0
    1678 0FE4 11/19 23:09:44.634 18 dsmreceiversubtaskbase.cpp(178) [0000016597120F50] 678E789A-B867-4E85-8413-A888198B6A7B VERBOSE CDsmReceiverSubTaskBase: processing completion (signature:0xaabbcc02 type:0x15, state:1)
    1678 0FE4 11/19 23:09:44.634 18 dsmreceiversubtaskbase.cpp(256) [0000016597120F50] 678E789A-B867-4E85-8413-A888198B6A7B WARNING Failed: Hr: = [0x80070040] CDsmReceiverSubTaskBase received completion for session error in WAIT state
    1678 0FE4 11/19 23:09:44.634 18 dsmsubtaskbase.cpp(240) [0000016597120F50] 678E789A-B867-4E85-8413-A888198B6A7B WARNING Session error before data move completed

    CLIENT SIDE:

    - Log File:DPMRACurr.errlog

    2A60 22DC 11/19 23:09:44.708 20 session.cpp(1560) [000000C220D86090] 678E789A-B867-4E85-8413-A888198B6A7B NORMAL Hr: = [0x80070079] DM: Will attempt to post DM_SESSION_ERROR, pSes=000000C220D86090 rcv=0000000000000000 snd=000000C220D7D628 sesop=0000000000000000 seserr=0000000000000000
    2A60 295C 11/19 23:09:44.708 18 dsmsendersubtaskbase.cpp(162) [000000C220D7D390] 678E789A-B867-4E85-8413-A888198B6A7B WARNING Failed: Hr: = [0x80070079] CDsmSenderSubTaskBase received session error completion in WAIT state
    2A60 295C 11/19 23:09:44.708 18 dsmsubtaskbase.cpp(240) [000000C220D7D390] 678E789A-B867-4E85-8413-A888198B6A7B WARNING Session error before data move completed

    Any ideas?

    Thanks

    Regards


    Tuesday, November 20, 2018 4:01 AM

All replies

  • Hello!

    Thank you for your clear description and the error logs!

    The error regarding "The semaphore timeout period has expired (0x80070079)" is something many are having issues with in DPM 1807, there are some other threads about it as well.

    So this error is as of recent, and does it only occur to this one specific virtual machine?

    First let's make sure that you have the latest Microsoft Azure Recovery Services (MARS) agent installed.
    The latest version is 2.0.9145.0 and can be downloaded from here.

    Here's also a Wiki page that I have made that lists the different versions.

    Microsoft Azure Recovery Services / Azure Backup Agent: List of agent versions

    You can also refer to the page below on how to update the MARS / Azure Backup agent.

    Updating Azure Backup agents

    Best regards,
    Leon


    Blog: https://thesystemcenterblog.com LinkedIn:


    • Edited by Leon Laude Tuesday, November 20, 2018 8:01 AM
    Tuesday, November 20, 2018 7:58 AM
  • Hello Lean, this error occur in any virtual machine in that cluster. I think there is something wrong in DPM server. This error is recent because we are in the testing phase now to implement DPM solution.

    We don't use yet AZURE but we are going to implement, so we are going to implement the last version that you show us.

    We read all POSTs about this error but none apply and fix our case. 

    We don't have implemented throtling

    Any ideas or debug that we can implement?


    Thanks
    Regards


    Tuesday, November 20, 2018 6:43 PM
  • Hello, we installed the Microsoft Azure Recovery Services (MARS) agent version 2.0.9145.0 but the problem persist.

    Any ideas?

    Regards


    Wednesday, November 21, 2018 5:01 PM
  • Sorry for the late response! 

    Have you tried the following workaround to see whether it could help?

    How to modify the TCP/IP maximum retransmission timeout

    https://support.microsoft.com/en-gb/help/170359/how-to-modify-the-tcp-ip-maximum-retransmission-time-out


    Blog: https://thesystemcenterblog.com LinkedIn:

    Thursday, November 29, 2018 1:26 PM