• EN
Solved

Problem with Hyper-V restore: Failed to restore vm. Name: [Server] ChannelError: ConnectionReset (Veeam.Backup.Common.CAppException)

S
Userlevel 3

Hello!

I am trying to play with restoring one Hyper-V VM onto another Hyper-V server just to know what to expect in the future.

So I created the Backup job which backed up this VM to the Backup repository which in turn resides in the shared folder of the second Hyper-V physical machine, i.e. is the part of the second server.

After back up is done (very fast!)  I started Restore job of the Entire VM, and it fails. I tried all possible scenarios : restore entire VM, immediate restore with the following migration, I tried even importing this backup and restoring VM from imported file - ALL FAILED with the same symptoms: restoration starts very optimistically and energetically, going to the point of 45-46 GB of vhdx restoration, stops, nothing seems to be happening, only process timer shows it is still alive and ticking, and this frozen state continues for 5 to 8 hours just to get this ChannelError: ConnectionReset.

 

Thank you!

icon

Best answer by coolsport00 4 July 2023, 14:07

View original

7 comments

coolsport00
Userlevel 7
Badge +17

1 of many reasons why. Hard to say exactly. On your Veeam server, you can look in C:\ProgramData\Veeam\Backup, then find the folder name of your backup job and view logs to see what the issue may be. You may have Firewall running on your Hyper-V and/or Proxy servers causing connection issues. Could potentially be port issues, which you can review those req’s here. Another option to check even are system event logs on the Hyper-V Host you’re restoring to. Lastly, verify pre-req’s and limitations for Hyper-V restores here.

Shane Williford - Veeam VMCA/VMCE | Veeam Legend | VUG Leader | VCP-DCV | Twitter: @coolsport00
S
Userlevel 3

Thank you!

I have this log, can I post it over here?

S
Userlevel 3

In case of the firewall why is that it starts restoring successfully, going to 4% of the job, and after dies? Always 4%. It is strange to me.

coolsport00
Userlevel 7
Badge +17

Sure...you can post it 

Shane Williford - Veeam VMCA/VMCE | Veeam Legend | VUG Leader | VCP-DCV | Twitter: @coolsport00
S
Userlevel 3

I am trying to upload the log, but it hangs uploading.

S
Userlevel 3

This is the part of it:

 

Preparing for processing of disk D:\Virtual hard disks\Server2022.vhdx, resources: proxy 'SRV-10DC'
[03.07.2023 01:08:02] <28> Info         [HvWmiProxy:SRV-10DC] Closing connection
[03.07.2023 01:08:02] <28> Info         [CProxyRpcInvoker] RpcInvoker [33092577] was disposed
[03.07.2023 06:25:11] <01> Info         [HvWmiProxy:SRV-10DC] Opening connection
[03.07.2023 06:25:11] <01> Info         [CVeeamHvIntegrator]         [hv (SRV-10DC)] Connecting to HvIntegration service, host 'SRV-10DC', port '6163'.
[03.07.2023 06:25:11] <01> Info         Resolved by NTLM strategy ip addresses and host names: 10.0.0.10 SRV-10DC
[03.07.2023 06:25:11] <01> Info         [CProxyRpcInvoker] RpcInvoker [6168246] has been created. Host: [SRV-10DC:6163]
[03.07.2023 06:25:12] <41> Info         [WmiProxy:SRV-10DC] HviDestroyPlannedVm: <InputArguments><Hvi_RequestId value="000000000000000a" /><Hvi_TimeoutMs value="3600000" /><VmId value="ff1ba70a-a856-49b5-9df8-c6a5fa785439" /></InputArguments>
[03.07.2023 06:25:13] <01> Info         Removing configuration files from restore host after fail creation planned VM.
[03.07.2023 06:25:13] <01> Info                 [AP] (8450) command: 'Invoke: FileSystem.Cleanup { (EBoolean) Option.Remote = false; (EStringArray) FileList[] = { C:\ProgramData\Microsoft\Windows\Hyper-V\Virtual Machines\44be732e-91d7-418e-a5f4-01350ea1814d\44be732e-91d7-418e-a5f4-01350ea1814d.vmrs; C:\ProgramData\Microsoft\Windows\Hyper-V\Virtual Machines\44be732e-91d7-418e-a5f4-01350ea1814d\44be732e-91d7-418e-a5f4-01350ea1814d.vmgs; C:\ProgramData\Microsoft\Windows\Hyper-V\Virtual Machines\44be732e-91d7-418e-a5f4-01350ea1814d\44be732e-91d7-418e-a5f4-01350ea1814d.vmcx; }; (EStringArray) FolderList[] = { C:\ProgramData\Microsoft\Windows\Hyper-V\Virtual Machines\44be732e-91d7-418e-a5f4-01350ea1814d; }; (EInt32) TimeoutSec = 30; }'
[03.07.2023 06:25:13] <39> Info                   [AP] (8450) output: <VCPCommandResult result="true" exception="" />
[03.07.2023 06:25:13] <30> Info                   [AP] (8450) output: <VCPCommandArgs><Item key="FileList[]" type="EStringArray" value="" /><Item key="FolderList[]" type="EStringArray" value="" /></VCPCommandArgs>
[03.07.2023 06:25:13] <30> Info                   [AP] (8450) output: >
[03.07.2023 06:25:13] <01> Info             [AgentsSession] Disposing...
[03.07.2023 06:25:13] <01> Info             [AgentsSession] Removing agents connection
[03.07.2023 06:25:13] <01> Info                 [AP] (8450) disconnecting
[03.07.2023 06:25:13] <21> Info                   [AP] (8450) output: >
[03.07.2023 06:25:13] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:13] <01> Info             Disposing BaseAgentProtocol [0x5757a]
[03.07.2023 06:25:13] <01> Info             Disposing CSocketAgentService [0x312152], sessionId [5651]
[03.07.2023 06:25:13] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id 5651
[03.07.2023 06:25:13] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:13] <01> Info             Disposing BaseAgentProtocol [0x38b8b2d]
[03.07.2023 06:25:13] <01> Info             Disposing CSocketAgentService [0x3e7e49a], sessionId [8450]
[03.07.2023 06:25:13] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id 8450
[03.07.2023 06:25:13] <01> Info             Disposing CProxyAgent [0x3270971], agent id 7a1d436a-ff20-4e94-bcf5-b821105848d2
[03.07.2023 06:25:13] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:13] <01> Info             Disposing BaseAgentProtocol [0x359fcc4]
[03.07.2023 06:25:13] <01> Info             Disposing CSocketAgentService [0x229e2ec], sessionId [332f]
[03.07.2023 06:25:13] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id 332f
[03.07.2023 06:25:13] <01> Info             [AgentMngr] Stopping agent, id '7a1d436a-ff20-4e94-bcf5-b821105848d2'
[03.07.2023 06:25:13] <01> Info             [AgentMngr] Closing port before agent stop, id '7a1d436a-ff20-4e94-bcf5-b821105848d2'.
[03.07.2023 06:25:13] <01> Info             [AgentMngr] Sending signal to stop agent with timeout (10 sec), id 7a1d436a-ff20-4e94-bcf5-b821105848d2. Host: SRV-10DC.
[03.07.2023 06:25:13] <01> Info             [AgentMngr] Checking whether agent '7a1d436a-ff20-4e94-bcf5-b821105848d2' is alive on host 'SRV-10DC' with timeout.
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Checking whether agent '7a1d436a-ff20-4e94-bcf5-b821105848d2' is alive on host 'SRV-10DC' with timeout.
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Agent has been stopped, id '7a1d436a-ff20-4e94-bcf5-b821105848d2'
[03.07.2023 06:25:14] <01> Info         [CProxyRpcInvoker] RpcInvoker [15035499] was disposed
[03.07.2023 06:25:14] <01> Info             Disposing CBackupRepositoryClient [0x378fa51]
[03.07.2023 06:25:14] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:14] <01> Info             Disposing BaseAgentProtocol [0x14733be]
[03.07.2023 06:25:14] <01> Info             Disposing CSocketAgentService [0x380d1b0], sessionId [1387]
[03.07.2023 06:25:14] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id 1387
[03.07.2023 06:25:14] <01> Info             [ReconnectableSocket] Stop request was sent on [dc2f6e3d-f0b1-4ba8-ae09-8328e81c6d76].
[03.07.2023 06:25:14] <35> Info             [ReconnectableSocket][StopCondition] Stop confirmation was received on [dc2f6e3d-f0b1-4ba8-ae09-8328e81c6d76].
[03.07.2023 06:25:14] <35> Info             [ReconnectableSocket] Stop confirmation was sent on [dc2f6e3d-f0b1-4ba8-ae09-8328e81c6d76].
[03.07.2023 06:25:14] <35> Info             [ReconnectableSocket][StopCondition] Stop request was received on [dc2f6e3d-f0b1-4ba8-ae09-8328e81c6d76].
[03.07.2023 06:25:14] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:14] <01> Info             Disposing BaseAgentProtocol [0x3c258d1]
[03.07.2023 06:25:14] <01> Info             Disposing CSocketAgentService [0x1d51f59], sessionId [1f93]
[03.07.2023 06:25:14] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id 1f93
[03.07.2023 06:25:14] <01> Info             [ReconnectableSocket] Stop request was sent on [548804ad-a681-49d7-87b2-80ccd540bd71].
[03.07.2023 06:25:14] <38> Info             [ReconnectableSocket][StopCondition] Stop confirmation was received on [548804ad-a681-49d7-87b2-80ccd540bd71].
[03.07.2023 06:25:14] <37> Info             [ReconnectableSocket] Stop confirmation was sent on [548804ad-a681-49d7-87b2-80ccd540bd71].
[03.07.2023 06:25:14] <37> Info             [ReconnectableSocket][StopCondition] Stop request was received on [548804ad-a681-49d7-87b2-80ccd540bd71].
[03.07.2023 06:25:14] <01> Info             Disposing CRepositoryAgent [0x7e1a26], agent id c90008b6-bbf6-40c6-a017-717f372992cd
[03.07.2023 06:25:14] <19> Info                 [AP] (a983) command: 'Invoke: Generic.AbortReconnects '
[03.07.2023 06:25:14] <39> Info                   [AP] (a983) output: <VCPCommandResult result="true" exception="" />
[03.07.2023 06:25:14] <30> Info                   [AP] (a983) output: <VCPCommandArgs />
[03.07.2023 06:25:14] <30> Info                   [AP] (a983) output: >
[03.07.2023 06:25:14] <19> Info         [RemoteAgentSystemSession] Keep-alive thread operation is canceled, agentId: 'c90008b6-bbf6-40c6-a017-717f372992cd'
[03.07.2023 06:25:14] <01> Info                 [AP] Disposing client from thread 1
[03.07.2023 06:25:14] <01> Info             Disposing BaseAgentProtocol [0x3e64617]
[03.07.2023 06:25:14] <01> Info             Disposing CSocketAgentService [0x31876d6], sessionId [a983]
[03.07.2023 06:25:14] <01> Info             [SocketAgentService] Closing connection to agent 'SRV-10DC', id a983
[03.07.2023 06:25:14] <01> Info             Disposing CProxyAgent [0x3dc2d8e], agent id c90008b6-bbf6-40c6-a017-717f372992cd
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Stopping agent, id 'c90008b6-bbf6-40c6-a017-717f372992cd'
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Closing port before agent stop, id 'c90008b6-bbf6-40c6-a017-717f372992cd'.
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Sending signal to stop agent with timeout (10 sec), id c90008b6-bbf6-40c6-a017-717f372992cd. Host: SRV-10DC.
[03.07.2023 06:25:14] <01> Info             [AgentMngr] Checking whether agent 'c90008b6-bbf6-40c6-a017-717f372992cd' is alive on host 'SRV-10DC' with timeout.
[03.07.2023 06:25:15] <01> Info             [AgentMngr] Checking whether agent 'c90008b6-bbf6-40c6-a017-717f372992cd' is alive on host 'SRV-10DC' with timeout.
[03.07.2023 06:25:15] <01> Info             [AgentMngr] Agent has been stopped, id 'c90008b6-bbf6-40c6-a017-717f372992cd'
[03.07.2023 06:25:15] <01> Info         [CProxyRpcInvoker] RpcInvoker [53866394] was disposed
[03.07.2023 06:25:15] <18> Info         [RPC] Destroying RPC confirm session. Id: {f54ce51f-5321-496a-9536-decdfc46c849}
[03.07.2023 06:25:15] <01> Info         [CProxyRpcInvoker] RpcInvoker [1237054] was disposed
[03.07.2023 06:25:15] <01> Info             [StorageLock] Unlocking storage, lockId: 'LockId: 1b0e1941-6f16-4d8e-9a8b-bfbce8ee2b06, LeaseId: 78ef5099-e524-496d-896c-afd9edef9178'
[03.07.2023 06:25:15] <01> Info             [API] DestroyLease.Started, leaseId: [78ef5099-e524-496d-896c-afd9edef9178]
[03.07.2023 06:25:15] <01> Info             [API] DestroyLease.Success, leaseId: [78ef5099-e524-496d-896c-afd9edef9178]
[03.07.2023 06:25:15] <01> Error        Failed to restore vm. Name: [Server2022]
[03.07.2023 06:25:15] <01> Error        ChannelError: ConnectionReset (Veeam.Backup.Common.CAppException)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CClientAgentProtocol.WaitUntilWorking(Int32 timeout)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CClientAgentProtocol.DoAgentCommand(String command, String logCommand, Boolean doWait, Nullable`1 outputLogLevel)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CClientAgentProtocol.AgentProtocolSendCommandStub(String command, Boolean contextNoLog, String contextLogString)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CAgentInOutTextVcpStream.XmlBlobWrite(String value)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Common.CVcpCommand.Write(CVcpFeatureSet features, CVcpStreamBase stream)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Common.CVcpInvoker.Invoke(CVcpStreamBase stream, String command, CVcpCommandArgs inArgs, Boolean noLog)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CClientAgentProtocol.Invoke(String command, CVcpCommandArgs inArgs, Boolean noLog, Boolean agentNoLog)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClient.Invoke(String command, CVcpCommandArgs inArgs, Boolean noLog)
[03.07.2023 06:25:15] <01> Error        --- End of stack trace from previous location where exception was thrown ---
[03.07.2023 06:25:15] <01> Error           at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Common.ExceptionFactory.ThrowNecessaryAggregateException(IEnumerable`1 exceptionsCollection)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClientImpl.ConstructException(Exception exception, String error)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClient.ConstructException(Exception ex, String error, Object[] args)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClient.OnInvokeError(Exception e, String command, CVcpCommandArgs inArgs)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClient.Invoke(String command, CVcpCommandArgs inArgs, Boolean noLog)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.AgentProvider.CBackupClient.DataTransferSyncDisk(ISourceDiskSpec source, ITargetDiskSpec target, Boolean serverHandlesSource, String operationId, Boolean treatProcessedLikeReaded)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.HyperV.CHvRestoreDiskTransferAlg.RestoreVhdDisk(COIBFileInfo hvOibDisk, CHvVssRestoreTgtInfo vhdTarget, IStopSessionSync sessControl)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.HyperV.CHvRestoreDiskTransferAlg.ProcessDisk(CDiskTask diskTask, IStopSessionSync sessControl)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CParallelDiskProcessorImpl.ProcessDisk(CDiskTask diskTask, IDiskTransferAlg disksAlg)
[03.07.2023 06:25:15] <01> Error        --- End of stack trace from previous location where exception was thrown ---
[03.07.2023 06:25:15] <01> Error           at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CParallelDiskProcessor.ProcessDisks(CDiskTasksManager diskTasksManager, IDiskTransferAlg disksAlg)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CParallelDiskProcessor.ProcessDisks(IDiskTransferAlg disksAlg, IEnumerable`1 diskBackupObjects)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.HyperV.CHvVmRestoreBackupSource2015.RestoreVhd(IHvSharedDiskRestoreDispatcher sharedDiskRestoreDispatcher, CHvVssPreRestoreSpec preRestoreSpec, Boolean isFullRestore, CHvVmRestoredFileCollection restoredFilesCanBeNull)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CHvVmRestoreAlg2015.RestoreVmObject(IXmlLogger logger, IStopSessionSync sync, CHvWmiUtils wmiUtils, CHvVmRestoredFileCollection restoredFilesCanBeNull)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CHvVmRestoreAlg2015.RestoreVmObject(IStopSessionSync sync, IXmlLogger logger, Boolean isReplicaFailBack, Boolean vmSrcAndTgtHostsAreSame, CHvWmiUtils wmiUtils, CHvVmRestoredFileCollection restoredFilesCanBeNull, CHvVmSwitchPortInfo[]& restoreSwitches)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.CHvVmRestoreAlg2015.DoRestore(IStopSessionSync sync, IXmlLogger logger, Boolean isReplicaFailBack, Boolean restoreToOriginalLocation, CHvVmRestoredFileCollection restoredFiles)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.HyperV.CHvVmRestorer.RestoreVmOnNode(CHvDbHost trgHost, IHvVmBackupRestoreDataSource dataSource, IDiskProcessor diskProcessor, CRestoreFilesParallelProgressWriter progress, IStopSessionSync sync, CRestoreTaskSession taskSession)
[03.07.2023 06:25:15] <01> Error           at Veeam.Backup.Core.HyperV.CHvVmRestorer.Veeam.Backup.Core.IVmRestorer.DoRestore(IStopSessionSync sync, IStorageAccessor accessor)
[03.07.2023 06:25:15] <01> Error        ChannelError: ConnectionReset (Veeam.Backup.Common.ConnectionException)
[03.07.2023 06:25:15] <01> Info         Job Restore Task operation result: 'ChannelError: ConnectionReset

coolsport00
Userlevel 7
Badge +17

Nothing definitive stands out to me @StingerAlex . I see from the log, your restore appears to start at “1:08”, then nothing is written to the log until “6:25”. It then looks like Veeam is attempting connection/reconnection a few times before it then errors out. But, I couldn’t see any definitive reason, port/fw or otherwise. At this point I recommend contacting Support to see what they say.

Shane Williford - Veeam VMCA/VMCE | Veeam Legend | VUG Leader | VCP-DCV | Twitter: @coolsport00

Comment


Terms & Conditions