VMware Cloud Community
Bird8023
Contributor
Contributor

Vmotion a virtual machine failed with error: Failed to resume on the destination: Failure

Hello, I have a question for Vmotion a virtual machine failed.

The vmvare.log reported: Failed to resume on the destination: Failure.  Exiting...

The vmkernel.log :

2017-07-20T07:19:24.315Z cpu12:4091250)Migrate: vm 4091262: 3382: Setting FSR info: Dest ts = 1500506207908405, src ip = <127.0.0.1> dest ip = <127.0.0.1> Dest wid = 0 using UNSHARED swap

2017-07-20T07:19:24.317Z cpu12:4091250)WARNING: Migrate: 3451: 1500506207908405 😧 Unable to set NUMA affinity mask for world 4091262

2017-07-20T07:19:24.317Z cpu12:4091250)Hbr: 3394: Migration start received (worldID=4091262) (migrateType=2) (event=0) (isSource=0) (sharedConfig=0)

2017-07-20T07:19:24.395Z cpu4:4090868)Migrate: vm 4090869: 3382: Setting FSR info: Source ts = 1500506207908405, src ip = <127.0.0.1> dest ip = <127.0.0.1> Dest wid = 4091262 using UNSHARED swap

2017-07-20T07:19:24.395Z cpu4:4090868)Hbr: 3394: Migration start received (worldID=4090869) (migrateType=2) (event=0) (isSource=1) (sharedConfig=0)

2017-07-20T07:19:24.823Z cpu14:4091265)Swap: vm 4091262: 1419: Successfully initialized normal swapfile.

2017-07-20T07:19:24.823Z cpu14:4091265)FSR: 1500: 1500506207908405 S: Swap copy helper world starting swap copy.

2017-07-20T07:19:24.823Z cpu14:4091265)SVM: 5041: SkipZero 0, dstFsBlockSize 0, preallocateBlocks 0, vmfsOptimizations 1, useBitmapCopy 0, skipPlugGrain 0

2017-07-20T07:19:24.823Z cpu14:4091265)SVM: 5139: SVM_MakeDev.5139: Creating device 1d2ca53-1aecc89-svmmirror: Success

2017-07-20T07:19:24.823Z cpu14:4091265)SVM: 5188: Created device 1d2ca53-1aecc89-svmmirror, primary 1d2ca53, secondary 1aecc89

2017-07-20T07:19:24.826Z cpu2:4091266)SVM: 2858: scsi255:255 Completed copy in 3 ms. vmmLeaderID = 4090869.

2017-07-20T07:19:24.826Z cpu2:4091266)FSR: 1186: 1500506207908405 S: Swap copy complete successfully.

2017-07-20T07:19:24.826Z cpu14:4091265)FSR: 1534: 1500506207908405 S: Swap copy complete.

2017-07-20T07:19:26.765Z cpu15:33056)ScsiDeviceIO: 2646: Cmd(0x439d808c6d00) 0x1a, CmdSN 0x582c57 from world 0 to dev "naa.690b11c00f2a300020bc0d721364929d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-07-20T07:19:27.097Z cpu5:4090869)NetPort: 1780: disabled port 0x20102e5

2017-07-20T07:19:27.097Z cpu5:4090874)VSCSI: 6699: handle 69883(vscsi0:0):Destroying Device for world 4090869 (pendCom 0)

2017-07-20T07:19:27.100Z cpu6:4090871)SVM: 5041: SkipZero 0, dstFsBlockSize 0, preallocateBlocks 0, vmfsOptimizations 1, useBitmapCopy 0, skipPlugGrain 0

2017-07-20T07:19:27.100Z cpu6:4090871)SVM: 5139: SVM_MakeDev.5139: Creating device 1deca69-29ccc8d-svmmirror: Success

2017-07-20T07:19:27.100Z cpu6:4090871)SVM: 5188: Created device 1deca69-29ccc8d-svmmirror, primary 1deca69, secondary 29ccc8d

2017-07-20T07:19:27.101Z cpu5:4090869)NetPort: 1573: enabled port 0x20102e5 with mac 00:50:56:8c:57:9a

2017-07-20T07:19:27.107Z cpu5:4090874)SVM: 5041: SkipZero 1, dstFsBlockSize 1048576, preallocateBlocks 1, vmfsOptimizations 1, useBitmapCopy 0, skipPlugGrain 0

2017-07-20T07:19:27.107Z cpu5:4090874)SVM: 5139: SVM_MakeDev.5139: Creating device 208ca6c-1ffcc8a-svmmirror: Success

2017-07-20T07:19:27.107Z cpu5:4090874)SVM: 5188: Created device 208ca6c-1ffcc8a-svmmirror, primary 208ca6c, secondary 1ffcc8a

2017-07-20T07:19:27.108Z cpu5:4090874)VSCSI: 4011: handle 69885(vscsi0:0):Creating Virtual Device for world 4090869 (FSS handle 38652525) numBlocks=83886080 (bs=512)

2017-07-20T07:19:27.108Z cpu5:4090874)VSCSI: 273: handle 69885(vscsi0:0):Input values: res=0 limit=-1 bw=-1 Shares=-1

2017-07-20T07:19:27.206Z cpu9:4091271)SVM: 2858: scsi0:0 Completed copy in 89 ms. vmmLeaderID = 4090869.

2017-07-20T07:19:27.290Z cpu12:2674309)ScsiDeviceIO: 2646: Cmd(0x439d809540c0) 0x1a, CmdSN 0x582c8a from world 0 to dev "naa.690b11c00f2a300020bc0d721364929d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-07-20T07:19:27.291Z cpu12:2674309)ScsiDeviceIO: 2646: Cmd(0x439d809540c0) 0x1a, CmdSN 0x582c8f from world 0 to dev "naa.690b11c00f2a300020bc0d721364929d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-07-20T07:19:27.298Z cpu1:4091272)SVM: 2851: file# 0: Completed copy in 80 ms. vmmLeaderID = 4090869.

2017-07-20T07:19:27.305Z cpu1:4090869)NetPort: 1780: disabled port 0x20102e5

2017-07-20T07:19:27.305Z cpu1:4090874)VSCSI: 6699: handle 69885(vscsi0:0):Destroying Device for world 4090869 (pendCom 0)

2017-07-20T07:19:27.306Z cpu1:4090874)SVM: 2428: SVM Mirrored mode IO stats for device: 208ca6c-1ffcc8a-svmmirror

2017-07-20T07:19:27.306Z cpu1:4090874)SVM: 2432: Total # IOs mirrored: 0, Total # IOs sent only to source: 0, Total # IO deferred by lock: 0

2017-07-20T07:19:27.306Z cpu1:4090874)SVM: 2436: Deferred IO stats - Max: 0, Total: 0, Avg: 1 (msec)

2017-07-20T07:19:27.306Z cpu1:4090874)SVM: 2450: Destroyed device 208ca6c-1ffcc8a-svmmirror

2017-07-20T07:19:27.308Z cpu1:4090874)SVM: 2428: SVM Mirrored mode IO stats for device: 1deca69-29ccc8d-svmmirror

2017-07-20T07:19:27.308Z cpu1:4090874)SVM: 2432: Total # IOs mirrored: 0, Total # IOs sent only to source: 0, Total # IO deferred by lock: 0

2017-07-20T07:19:27.308Z cpu1:4090874)SVM: 2436: Deferred IO stats - Max: 0, Total: 0, Avg: 1 (msec)

2017-07-20T07:19:27.308Z cpu1:4090874)SVM: 2450: Destroyed device 1deca69-29ccc8d-svmmirror

2017-07-20T07:19:27.529Z cpu0:4091250)Swap: vm 4091262: 1289: Swapfile already initialized. No work to do.

2017-07-20T07:19:27.574Z cpu3:4091250)VSCSI: 4011: handle 69886(vscsi0:0):Creating Virtual Device for world 4091262 (FSS handle 44092557) numBlocks=83886080 (bs=512)

2017-07-20T07:19:27.574Z cpu3:4091250)VSCSI: 273: handle 69886(vscsi0:0):Input values: res=0 limit=-2 bw=-1 Shares=1000

2017-07-20T07:19:27.642Z cpu4:3265078)ScsiDeviceIO: 2646: Cmd(0x439d84839ec0) 0x1a, CmdSN 0x582d21 from world 0 to dev "naa.690b11c00f2a300020bc0d721364929d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-07-20T07:19:27.643Z cpu9:4091262)VMMVMKCall: 235: Received INIT from world 4091262

2017-07-20T07:19:27.643Z cpu4:3265078)ScsiDeviceIO: 2646: Cmd(0x439d84839ec0) 0x1a, CmdSN 0x582d26 from world 0 to dev "naa.690b11c00f2a300020bc0d721364929d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-07-20T07:19:27.650Z cpu1:34778)LVM: 10060: Device naa.600b342b1d453c8db63dd6856d0000db:1 detected to be a snapshot:

2017-07-20T07:19:27.650Z cpu1:34778)LVM: 10067:   queried disk ID: <type 2, len 22, lun 11, devType 0, scsi 0, h(id) 8686437659640839581>

2017-07-20T07:19:27.650Z cpu1:34778)LVM: 10074:   on-disk disk ID: <type 2, len 22, lun 0, devType 0, scsi 0, h(id) 9512531387408291070>

2017-07-20T07:19:27.653Z cpu1:34778)LVM: 10060: Device naa.600b3429a5bbbbfdfbb1d10c6d0000db:1 detected to be a snapshot:

2017-07-20T07:19:27.653Z cpu1:34778)LVM: 10067:   queried disk ID: <type 2, len 22, lun 12, devType 0, scsi 0, h(id) 3064839419528190981>

2017-07-20T07:19:27.653Z cpu1:34778)LVM: 10074:   on-disk disk ID: <type 2, len 22, lun 0, devType 0, scsi 0, h(id) 9512531387408291070>

2017-07-20T07:19:27.655Z cpu9:4091265)SVM: 2463: Error destroying device 1d2ca53-1aecc89-svmmirror (Busy)

2017-07-20T07:19:27.655Z cpu9:4091265)WARNING: FSR: 1269: 1500506207908405 S: Failed to destroy mirror node for swap file: Busy

2017-07-20T07:19:27.655Z cpu9:4091265)WARNING: FSR: 1589: 1500506207908405 S: Swap copy helper failed, exiting.

2017-07-20T07:19:27.655Z cpu9:4091265)WARNING: Migrate: 270: 1500506207908405 S: Failed: Busy (0xbad0004) @0x418036c1231e

2017-07-20T07:19:27.656Z cpu0:4091262)WARNING: FSR: 4726: 1500506207908405 😧 Failed to tranfer the swap file from source VM to destination VM.

2017-07-20T07:19:27.656Z cpu0:4091262)WARNING: Migrate: 270: 1500506207908405 😧 Failed: Failure (0xbad0001) @0x418037cc01d6

2017-07-20T07:19:27.666Z cpu4:4090868)WARNING: Migrate: 5451: 1500506207908405 S: Migration considered a failure by the VMX.  It is most likely a timeout, but check the VMX log for the true error.

2017-07-20T07:19:27.680Z cpu1:4091275)WARNING: Migrate: 5451: 1500506207908405 😧 Migration considered a failure by the VMX.  It is most likely a timeout, but check the VMX log for the true error.

And then, I could shutdown this vm, but it couldn't be poweron again. The vmkernel.log reported that:

2017-07-20T09:25:52.430Z cpu2:4172955)FSS: 6146: Failed to open file 'zmx_hot-3-d0fd9b24.vswp'; Requested flags 0x8, world: 4172955 [vmx], (Existing flags 0x8, world: 4090868 [unknown]): Busy

2017-07-20T09:25:52.430Z cpu2:4172955)WARNING: SwapFileOps: vm 4172956: 286: Failed to open swap file '/vmfs/volumes/5965f31b-a9168818-fc27-90b11c095e3c/zmx_hot-3_3/zmx_hot-3-d0fd9b24.vswp': Busy

2017-07-20T09:25:52.430Z cpu2:4172955)WARNING: Swap: 3547: Failed to initialize swap file '/vmfs/volumes/5965f31b-a9168818-fc27-90b11c095e3c/zmx_hot-3_3/zmx_hot-3-d0fd9b24.vswp' : Busy

Tags (1)
Reply
0 Kudos
12 Replies
vijayrana968
Virtuoso
Virtuoso

What is the swap file configuration you have? Do you have configured separate datastore for all VM's swap file? Also, are you doing vmotion or svmotion ?

As you can see in logs, swap file transfer is failed from source host to destination host.

Reply
0 Kudos
Bird8023
Contributor
Contributor

I was doing svmotion, the swap file and VM‘s swap file were configured in the same directory.

Can the io poor performance lead to this question?

In addition, after I restarted the esxi, the VM could be powered on as usual.

Reply
0 Kudos
vijayrana968
Virtuoso
Virtuoso

This could be due to file locks as it is locked by a host in cluster. In your case probably it was source host locking swap file and when you restarted host it clear the lock. following steps need to investigate in case of this issue Investigating virtual machine file locks on ESXi (10051) | VMware KB 

Reply
0 Kudos
Bird8023
Contributor
Contributor

Thanks a lot for your advice.

But I still don't know why the svmtion VM failed, and why swap file transfer is failed.

Do you know any possible reason for this?

Reply
0 Kudos
vijayrana968
Virtuoso
Virtuoso

Can you upload vmeare.log file as attachment !

Reply
0 Kudos
dekoshal
Hot Shot
Hot Shot

For vm power on issue look into below kb:

Powering on a virtual machine fails with the error: Failed to initialize swap file '/Datastorepath/s...

For vmotion, run the vmotion and capture the logs from vmware.log ( located in working directory of the VM) and hostd.log (located in var/log) and provide the log snippet here.

If you found this or any other answer helpful, please consider the use of the Correct or Helpful to award points.

Best Regards,

Deepak Koshal

CNE|CLA|CWMA|VCP4|VCP5|CCAH

Reply
0 Kudos
Bird8023
Contributor
Contributor

vmware.log key words:

     2017-07-20T07:19:27.656Z| vcpu-0| W110: Migrate: Failed to resume on the destination: Failure.  Exiting...

hostd.log key words:

     2017-07-20T07:19:27.970Z info hostd[20740B70] [Originator@6876 sub=Vcsvc.VMotionDst (1500506207908405)] ResolveCb: Failed with fault: (vim.fault.GenericVmConfigFault) {

vmkernel.log key words:

     2017-07-20T07:19:27.655Z cpu9:4091265)SVM: 2463: Error destroying device 1d2ca53-1aecc89-svmmirror (Busy)

Reply
0 Kudos
Bird8023
Contributor
Contributor

Thanks your reply.

I upload log files as attachment replied to vijayrana968 at

Reply
0 Kudos
dekoshal
Hot Shot
Hot Shot

Check Below kb for swap busy issue.

2017-07-20T07:19:51.792Z cpu1:32843)WARNING: Swap: vm 4090869: 3298: Failed to unlink /vmfs/volumes/5965f31b-a9168818-fc27-90b11c095e3c/zmx_hot-3_3/zmx_hot-3-d0fd9b24.vswp: Busy

Powering on a virtual machine fails with the error: Failed to initialize swap file '/Datastorepath/s...

Why Source and destination IP are same. Were you trying to vmotion vm on the same host?

2017-07-20T06:49:30.028Z info hostd[217C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5965f31b-a9168818-fc27-90b11c095e3c/zmx_hot-4_6/zmx_hot-4.vmx opID=305f1540-11-4f-7d55 user=vpxuser:VSPHERE.LOCAL\Administrator] VMotionPrepare: srcMgmtIp=172.17.145.69

2017-07-20T06:49:30.028Z info hostd[217C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5965f31b-a9168818-fc27-90b11c095e3c/zmx_hot-4_6/zmx_hot-4.vmx opID=305f1540-11-4f-7d55 user=vpxuser:VSPHERE.LOCAL\Administrator] VMotionPrepare: dstMgmtIp=172.17.145.69

Multiple storage issue that requires your attantion. Please check if problem VM is on the problem datastore or not. That could be cause of the issue.

2017-07-20T10:38:32.719Z cpu15:34187)LVM: 10060: Device naa.600b342b1d453c8db63dd6856d0000db:1 detected to be a snapshot:

2017-07-20T10:38:32.719Z cpu15:34187)LVM: 10067:   queried disk ID: <type 2, len 22, lun 11, devType 0, scsi 0, h(id) 8686437659640839581>

2017-07-20T10:38:32.719Z cpu15:34187)LVM: 10074:   on-disk disk ID: <type 2, len 22, lun 0, devType 0, scsi 0, h(id) 9512531387408291070>

2017-07-20T10:38:32.721Z cpu15:34187)LVM: 10060: Device naa.600b3429a5bbbbfdfbb1d10c6d0000db:1 detected to be a snapshot:

2017-07-20T10:38:32.721Z cpu15:34187)LVM: 10067:   queried disk ID: <type 2, len 22, lun 12, devType 0, scsi 0, h(id) 3064839419528190981>

2017-07-20T10:38:32.721Z cpu15:34187)LVM: 10074:   on-disk disk ID: <type 2, len 22, lun 0, devType 0, scsi 0, h(id) 9512531387408291070>

2017-07-20T10:38:32.728Z cpu15:34187)LVM: 10060: Device naa.600b342b1f74fc9dba40d35abd0000db:1 detected to be a snapshot:

2017-07-20T10:35:07.992Z cpu11:34408)Vol3: 1072: Could not open device '5966c0f8-2d7994db-b383-b82a72d56f26' for volume open: Not found

2017-07-20T10:35:07.992Z cpu11:34408)LVM: 5486: Could not open device naa.600b3422d469047d9ecad2fbdd0000db:1, vol [5966c0f8-2d7994db-b383-b82a72d56f26, 5966c0f8-2d7994db-b383-b82a72d56f26, 1]: LVM device unreachable

If you found this or any other answer helpful, please consider the use of the Correct or Helpful to award points.

Best Regards,

Deepak Koshal

CNE|CLA|CWMA|VCP4|VCP5|CCAH

https://in.linkedin.com/in/dkoshal

Reply
0 Kudos
vijayrana968
Virtuoso
Virtuoso

Is it vsan data store ?

Reply
0 Kudos
Bird8023
Contributor
Contributor

yeah,it is Macrosan.

Reply
0 Kudos
Bird8023
Contributor
Contributor

I was doing svmotiion between two datastore, but on the same host. In addition, the svmotion not in snapshot. 

Reply
0 Kudos