recover fails with "configuration file failed" message

[vmmerlin]

Hi,

an attempt to recover a VM using vSphere Replication and WebClient fails with the following message:

"Processing recovered virtual machine 'testvm' configuration file failed."

The setup:

• one vCenter 5.1U1 on Windows 2008
• 2 ESXi Hosts 5.1U1
• Source VM on ESXi1 on local datastore
• Replica on ESXi2 on FC datastore
• one VRS running on ESXi2 (VRS 5.1.1.0)
• RPO 15min
• replication was setup more than 8 hours ago, replica can be seen on datastore
• user "Administrator" has full priviledge (default)

Trigger the failure:

• Poweroff ESXi1 (VM is lost, because it's on local datastore)
• recovery attempt through WebClient fails at 40 percent

I use a different folder in "VMs & Templates"-View to avoid VMs having the same name in the same folder.

I generated a log bundle and had a look at "_var_log_vmware_hbrsrv-1.log". There I can see, that VRS has access to the datastore, where the replica is. VRS successfully copy/rename files like .vmx, .vmxf and .nvram.

Then VRS tries the disk:

from log file:

---

2013-06-20T08:06:27.948Z [7FE40B723700 verbose 'HostPicker' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] AffinityHostPicker choosing host host-12 for context '[] /vmfs/volumes/4fc738a3-11a8f647-b2e
2-0022196a6aad/testvm'
2013-06-20T08:06:27.954Z [7FE40B723700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] Waiting for result for task haTask--vim.VirtualDiskManager.queryVirtualDiskInfo-421473350
2013-06-20T08:06:27.957Z [7FE4080D5700 info 'RemoteTask'] Task haTask--vim.VirtualDiskManager.queryVirtualDiskInfo-421473350 got result
2013-06-20T08:06:27.959Z [7FE40B723700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] Completing task haTask--vim.VirtualDiskManager.queryVirtualDiskInfo-421473350 after 0 sec (success)
2013-06-20T08:06:27.959Z [7FE40B723700 verbose 'HostPicker' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] AffinityHostPicker choosing host host-12 for context '[] /vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm'
2013-06-20T08:06:27.961Z [7FE40B723700 info 'Host' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] NFC creating session to target: 10.10.50.3 port: 902
2013-06-20T08:06:28.008Z [7FE403F3C700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:28.008Z [7FE403F3C700 verbose 'SessionManager'] hbr.replica.Group.GetCurrentRpoViolation: authorized
2013-06-20T08:06:28.096Z [7FE40B723700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: SELECT * FROM ReplicatedDisk WHERE (diskID == 'RDID-2346a4fe-c786-4ec8-a902-c7a5bd6192cf');
2013-06-20T08:06:28.096Z [7FE40B723700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: SELECT * FROM DiskInstance WHERE (diskInstanceKey == 186);
2013-06-20T08:06:28.097Z [7FE40B723700 verbose 'HostPicker' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] AffinityHostPicker choosing host host-12 for context '[] /vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm'
2013-06-20T08:06:28.100Z [7FE40B723700 info 'Host' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] NFC creating session to target: 10.10.50.3 port: 902
2013-06-20T08:06:28.375Z [7FE40B723700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: UPDATE OR ROLLBACK GroupImage SET isReapable = 0 WHERE (groupInstanceKey == 186);
2013-06-20T08:06:28.380Z [7FE40B723700 info 'Image' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05:6aad99db-136f-4685-a1ec-b89cde8e8c05] Made fail-over image hbr.replica.GroupImage:Hbr.Replica.GroupImage.00000000000000ba/GID-b0fd0850-80e9-48ce-9763-c3a975b48115:1FO
2013-06-20T08:06:28.388Z [7FE408116700 verbose 'SessionManager'] hbr.replica.GroupImage.GetVirtualMachines: authorized
2013-06-20T08:06:29.011Z [7FE408053700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:30.014Z [7FE40B723700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:31.016Z [7FE408116700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:32.019Z [7FE40B723700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:33.021Z [7FE408094700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:34.024Z [7FE408157700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:35.027Z [7FE40B8B2700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:36.029Z [7FE403F7D700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:37.032Z [7FE40B7E6700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:38.035Z [7FE403F7D700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:38.863Z [7FE40B7E6700 verbose 'SessionManager'] hbr.replica.ReplicationManager.GetServerStats: authorized
2013-06-20T08:06:39.037Z [7FE40B7A5700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:40.039Z [7FE408094700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:41.042Z [7FE40B723700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:42.045Z [7FE40B7E6700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:43.047Z [7FE40B7A5700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:44.050Z [7FE408116700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:45.052Z [7FE408094700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:46.055Z [7FE408116700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:47.057Z [7FE40B723700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:48.060Z [7FE408094700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
2013-06-20T08:06:49.063Z [7FE408053700 verbose 'SessionManager'] vmodl.query.PropertyCollector.waitForUpdatesEx: authorized
---

and then VRS deletes the files:

---

2013-06-20T08:06:49.845Z [7FE40B7A5700 verbose 'SessionManager'] hbr.replica.GroupImage.revert: authorized
2013-06-20T08:06:49.845Z [7FE40B7A5700 info 'Image' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] Reverting image Hbr.Replica.GroupImage.00000000000000ba/GID-b0fd0850-80e9-48ce-9763-c3a975b48115:1FO; type FO; state created
2013-06-20T08:06:49.845Z [7FE40B7A5700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: UPDATE OR ROLLBACK GroupImage SET isReapable = 1 WHERE (groupInstanceKey == 186);
2013-06-20T08:06:49.853Z [7FE40B7A5700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: INSERT OR ROLLBACK INTO PersistentCleanups (relPath, cleanupType, dsPath, diskType) VALUES ('testvm/testvm.vmx', 0, '4fc738a3-11a8f647-b2e2-0022196a6aad', 0);
--> SELECT LAST_INSERT_ROWID();
2013-06-20T08:06:49.857Z [7FE40B7A5700 verbose 'HostPicker' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] AffinityHostPicker choosing host host-12 for context '[] /vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm'
2013-06-20T08:06:49.864Z [7FE40B7A5700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] Waiting for result for task haTask--vim.FileManager.delete-421473364
2013-06-20T08:06:49.870Z [7FE40B7A5700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] Completing task haTask--vim.FileManager.delete-421473364 after 0 sec (success)
2013-06-20T08:06:49.870Z [7FE40B7A5700 info 'PersistentCleanup' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] The file '/vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm/testvm.vmx' (key=565) was cleaned up successfully.
2013-06-20T08:06:49.870Z [7FE40B7A5700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: DELETE FROM PersistentCleanups WHERE (key == 565);
2013-06-20T08:06:49.875Z [7FE40B7A5700 verbose 'Db' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] SQL code: INSERT OR ROLLBACK INTO PersistentCleanups (relPath, cleanupType, dsPath, diskType) VALUES ('testvm/testvm.vmxf', 0, '4fc738a3-11a8f647-b2e2-0022196a6aad', 0);
--> SELECT LAST_INSERT_ROWID();
2013-06-20T08:06:49.879Z [7FE40B7A5700 verbose 'HostPicker' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] AffinityHostPicker choosing host host-12 for context '[] /vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm'
2013-06-20T08:06:49.885Z [7FE40B7A5700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] Waiting for result for task haTask--vim.FileManager.delete-421473366
2013-06-20T08:06:49.890Z [7FE40B7A5700 verbose 'RemoteTask' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] Completing task haTask--vim.FileManager.delete-421473366 after 0 sec (success)
2013-06-20T08:06:49.890Z [7FE40B7A5700 info 'PersistentCleanup' opID=6aad99db-136f-4685-a1ec-b89cde8e8c05] The file '/vmfs/volumes/4fc738a3-11a8f647-b2e2-0022196a6aad/testvm/testvm.vmxf' (key=566) was cleaned up successfully.
[...]

---

Does anyone know the reason for the failure?

Thank you,

vmmerlin

[mvalkanov]

Hi,

Please check logs at /opt/vmware/hms/logs.

VRMS instructs VR server to create VM image from the replicated files. After that VRMS tries to remove replication settings and update disk paths in the .vmx in the image. It fails for some reason. After the failure VRMS instructs VR server to revert the replica image, so that recovery can be re-tried.

Regards,

Martin

[vmmerlin]

Thank you for your fast answer.

It seems VRMS has a problem to access the datastore.

I've checked, whether VRMS can resolve the vCenter Server hostname and ping the vCenter Server. Fine.

In the hms log file a Error is logged:

2013-06-20 08:06:49.789 ERROR jvsl.fileaccess [hms-jobs-main-thread-66] (..jvsl.fileaccess.VcFileAccess) operationID=6aad99db-136f-4685-a1ec-b89cde8e8c05 | Download of file com.vmware.jvsl.fileaccess.DatastoreFile:
filePath = testvm/testvm.vmx,
datacenterPath = Training,
datastoreName = Spare-50 through vCenter server VC50-REPL-TEST.vmeduc.local failed
com.vmware.vim.vmomi.client.common.UnexpectedStatusCodeException: Unexpected status code: 500
        at com.vmware.jvsl.fileaccess.FileOperationResponse.setResponse(FileOperationResponse.java:54)
        at com.vmware.jvsl.fileaccess.impl.HttpFileClientImpl.run(HttpFileClientImpl.java:568)
        at com.vmware.jvsl.fileaccess.impl.HttpFileClientImpl.getFile(HttpFileClientImpl.java:481)
        at com.vmware.jvsl.fileaccess.VcFileAccess$1.run(VcFileAccess.java:102)
        at com.vmware.jvsl.fileaccess.VcFileAccess.doFileAccess(VcFileAccess.java:66)
        at com.vmware.jvsl.fileaccess.VcFileAccess.download(VcFileAccess.java:97)
        at com.vmware.hms.recovery.RecoverJobImpl.updateVmx(RecoverJobImpl.java:459)
        at com.vmware.hms.recovery.RecoverJobImpl.recoverGroupWithTask(RecoverJobImpl.java:1437)
        at com.vmware.hms.recovery.RecoverJobImpl.start(RecoverJobImpl.java:264)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at com.vmware.jvsl.job.impl.BaseJobDispatcher.handleMessage(BaseJobDispatcher.java:88)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher.access$000(ExecutorJobDispatcher.java:24)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher$1.run(ExecutorJobDispatcher.java:48)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$RunnableWithDiagnosticContext.run(LoggerOpIdConfigurator.java:133)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$2.run(LoggerOpIdConfigurator.java:100)
        at com.vmware.jvsl.sessions.net.impl.TlsPreservingWrapper$2.run(TlsPreservingWrapper.java:47)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
2013-06-20 08:06:49.790 ERROR hms.recovery [hms-jobs-main-thread-66] (..hms.recovery.RecoverJobImpl) operationID=6aad99db-136f-4685-a1ec-b89cde8e8c05 | Failed to update vmx configuration file of recovered VM: com.vmware.jvsl.fileaccess.DownloadException: Download failed
com.vmware.jvsl.fileaccess.DownloadException: Download failed
        at com.vmware.jvsl.fileaccess.VcFileAccess.download(VcFileAccess.java:112)
        at com.vmware.hms.recovery.RecoverJobImpl.updateVmx(RecoverJobImpl.java:459)
        at com.vmware.hms.recovery.RecoverJobImpl.recoverGroupWithTask(RecoverJobImpl.java:1437)
        at com.vmware.hms.recovery.RecoverJobImpl.start(RecoverJobImpl.java:264)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at com.vmware.jvsl.job.impl.BaseJobDispatcher.handleMessage(BaseJobDispatcher.java:88)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher.access$000(ExecutorJobDispatcher.java:24)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher$1.run(ExecutorJobDispatcher.java:48)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$RunnableWithDiagnosticContext.run(LoggerOpIdConfigurator.java:133)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$2.run(LoggerOpIdConfigurator.java:100)
        at com.vmware.jvsl.sessions.net.impl.TlsPreservingWrapper$2.run(TlsPreservingWrapper.java:47)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
Caused by: com.vmware.vim.vmomi.client.common.UnexpectedStatusCodeException: Unexpected status code: 500
        at com.vmware.jvsl.fileaccess.FileOperationResponse.setResponse(FileOperationResponse.java:54)
        at com.vmware.jvsl.fileaccess.impl.HttpFileClientImpl.run(HttpFileClientImpl.java:568)
        at com.vmware.jvsl.fileaccess.impl.HttpFileClientImpl.getFile(HttpFileClientImpl.java:481)
        at com.vmware.jvsl.fileaccess.VcFileAccess$1.run(VcFileAccess.java:102)
        at com.vmware.jvsl.fileaccess.VcFileAccess.doFileAccess(VcFileAccess.java:66)
        at com.vmware.jvsl.fileaccess.VcFileAccess.download(VcFileAccess.java:97)
        ... 16 more
2013-06-20 08:06:49.790 ERROR hms.recovery [hms-jobs-main-thread-66] (..hms.recovery.RecoverJobImpl) operationID=6aad99db-136f-4685-a1ec-b89cde8e8c05 | Recovery failed for replication GID-b0fd0850-80e9-48ce-9763-c3a975b48115_SECONDARY: com.vmware.vim.binding.hms.fault.recovery.VmxUpdateFault:
vmName = testvm,
datastoreMoId = datastore-14
inherited from com.vmware.vim.binding.hms.fault.HmsMethodFault:
originalMessage = null
inherited from com.vmware.vim.binding.hms.fault.recovery.VmxUpdateFault: Processing recovered VM 'testvm' configuration file failed.
com.vmware.vim.binding.hms.fault.recovery.VmxUpdateFault:
vmName = testvm,
datastoreMoId = datastore-14
inherited from com.vmware.vim.binding.hms.fault.HmsMethodFault:
originalMessage = null
inherited from com.vmware.vim.binding.hms.fault.recovery.VmxUpdateFault: Processing recovered VM 'testvm' configuration file failed.
        at com.vmware.hms.recovery.RecoverJobImpl.recoverGroupWithTask(RecoverJobImpl.java:1444)
        at com.vmware.hms.recovery.RecoverJobImpl.start(RecoverJobImpl.java:264)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at com.vmware.jvsl.job.impl.BaseJobDispatcher.handleMessage(BaseJobDispatcher.java:88)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher.access$000(ExecutorJobDispatcher.java:24)
        at com.vmware.jvsl.job.executor.ExecutorJobDispatcher$1.run(ExecutorJobDispatcher.java:48)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$RunnableWithDiagnosticContext.run(LoggerOpIdConfigurator.java:133)
        at com.vmware.hms.util.executor.LoggerOpIdConfigurator$2.run(LoggerOpIdConfigurator.java:100)
        at com.vmware.jvsl.sessions.net.impl.TlsPreservingWrapper$2.run(TlsPreservingWrapper.java:47)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
2013-06-20 08:06:49.791 INFO  hms.recovery [hms-jobs-main-thread-66] (..hms.recovery.RecoverJobImpl) operationID=6aad99db-136f-4685-a1ec-b89cde8e8c05 | Reverting image RIID-880e02db-fb92-404e-96c4-8fabf6c534a1

[mvalkanov]

Hi,

The http get request to vCenter Server to access the file on the datastore failed with HTTP 500.

Details should be available in vpxd logs of vCenter Server.

You can also try to access via web browser some file on the same datastore:

https://vcenterserver/folder/path1/filename?dcPath=DatacenterName&dsName=datastoreName

For example: https://10.23.68.94/folder/testvm03/testvm03.vmx?dcPath=DC1&dsName=datastore1-5

Regards,

Martin

[vmmerlin]

In webbrowser I can access the the following URL:

https://vc50-repl-test/folder/testvm?dcPath=Training&dsName=Spare-50

In vCenter Logs I have the following message, when trying a failover:

---

2013-06-20T09:57:17.058+02:00 [04272 error 'HttpConnectionPool-000000'] [ConnectComplete] Connect failed to <cs p:000000000d9b88f0, TCP:esx50-2.vmeduc.local:443>; cnx: (null), error: class Vmacore::SystemException(A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. )
2013-06-20T09:57:17.058+02:00 [05560 warning 'VpxProfiler' opID=de5e0030] ClientAdapterBase::InvokeOnSoap: (esx50-2.vmeduc.local, vpxapi.VpxaService.nfcMakeTicketByDatastore) [SoapRpcTime] took 21031 ms
2013-06-20T09:57:17.058+02:00 [05560 error 'vpxdvpxdVmomi' opID=de5e0030] [VpxdClientAdapter] Got vmacore exception: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
2013-06-20T09:57:17.058+02:00 [05560 error 'vpxdvpxdVmomi' opID=de5e0030] [VpxdClientAdapter] Backtrace:
--> backtrace[00] rip 000000018018aa3a
--> backtrace[01] rip 0000000180102b18
--> backtrace[02] rip 0000000180103f3e
--> backtrace[03] rip 000000018008d6db
--> backtrace[04] rip 0000000180189f53
--> backtrace[05] rip 00000001801a5e5f
--> backtrace[06] rip 00000001801ad4fd
--> backtrace[07] rip 000000018019c6fa
--> backtrace[08] rip 0000000074122fdf
--> backtrace[09] rip 0000000074123080
--> backtrace[10] rip 000000007745f56d
--> backtrace[11] rip 0000000077693281
-->
2013-06-20T09:57:17.058+02:00 [04272 info 'commonvpxLro'] [VpxLRO] -- BEGIN task-internal-18744 -- host-9 -- VpxdInvtHostSyncHostLRO.Synchronize --
2013-06-20T09:57:17.058+02:00 [04272 warning 'vpxdvpxdInvtHostCnx'] [VpxdInvtHostSyncHostLRO] Connection not alive for host host-9
2013-06-20T09:57:17.058+02:00 [04272 warning 'vpxdvpxdInvtHostCnx'] [VpxdInvtHost::FixNotRespondingHost] Returning false since host is already fixed!
2013-06-20T09:57:17.058+02:00 [04272 warning 'vpxdvpxdInvtHostCnx'] [VpxdInvtHostSyncHostLRO] Failed to fix not responding host host-9
2013-06-20T09:57:17.058+02:00 [04272 warning 'vpxdvpxdInvtHostCnx'] [VpxdInvtHostSyncHostLRO] Connection not alive for host host-9
2013-06-20T09:57:17.058+02:00 [04272 error 'vpxdvpxdInvtHostCnx'] [VpxdInvtHostSyncHostLRO] FixNotRespondingHost failed for host host-9, marking host as notResponding
2013-06-20T09:57:17.058+02:00 [04272 info 'commonvpxLro'] [VpxLRO] -- FINISH task-internal-18744 -- host-9 -- VpxdInvtHostSyncHostLRO.Synchronize --
2013-06-20T09:57:17.058+02:00 [05560 info 'commonvpxLro' opID=de5e0030] [VpxLRO] -- FINISH task-internal-18710 --  -- vim.NfcService.fileManagement --
2013-06-20T09:57:17.058+02:00 [05560 info 'Default' opID=de5e0030] [VpxLRO] -- ERROR task-internal-18710 --  -- vim.NfcService.fileManagement: vmodl.fault.HostCommunication:
--> Result:
--> (vmodl.fault.HostCommunication) {
-->    dynamicType = <unset>,
-->    faultCause = (vmodl.MethodFault) null,
-->    msg = "",
--> }
--> Args:
-->

---

Does VRMS try to reach the datastore through the powered-off-host only?

Because esx50-2 is the first host in my scenario, which ist powered off.

(The datastore "Spare-50" is a Shared DS - both hosts can see the DS)

[mvalkanov]

Hi,

VRMS does not specify host, but issues the same get request as the web browser.

Please open an SR, so that the vCenter Server host picker issue for http file access is resolved.

Regards,

Martin

[vmmerlin]

thank you for help.

after powering on the esxi host (esx50-2) - the first host in my scenario - , the recovery process went fine. So it seems, that the recovery process picks the wrong esxi host, when accessing the datastore.

Since this is a PoC and not production environment I do not really need VMware Support. In addition, the test environment does only existiert until tomorrow. This may be not enough time for VMware support. Did I found a bug?

regards,

vmmerlin