vMotion failure during early power on

[mahmn]

I followed the vMotion wizard without any error. That means, the network interface in source and destination are set for vMotion.

After completing the wizard, I see this error in the task list:

A general system error occurred: Launch failure The VM failed to resume on the destination during early power on. ThrowableProxy.cause The VM failed to resume on the destination during early power on.

How can I check more for the cause?

[msripada]

You need to check the vmware.log and hostd.log on destination host when the vmotion failed.

cheers,

MS

[mahmn]

Where are these files?

[scott28tt]

On the host: ESXi Log File Locations

[mahmn]

The hostd.log file on the destination gets a lot of messages as I finish the wizard. According to the first few lines

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator] CopyFromEntry: Hostlog_Dump: Hostlog /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028-5b7e24c6.hlog

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    UUID: 00000000-0000-0000-0000-ac1f6b1b6dc6

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    MigID: 387457607475479822

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    HLState: none

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    ToFrom: none

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    MigType: invalid

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    OpType: nfc

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    WorldID: 0

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item Dir F "/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item Dir F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.nvram"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/vmware-3.log"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/vmware-2.log"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/vmware-1.log"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/vmware-0.log"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item File F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/vmware.log"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item Disk F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item Disk F "/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk"

2020-07-07T18:45:50.647Z info hostd[2100002] [Originator@6876 sub=vm opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-51-d2cd user=vpxuser:VSPHERE.LOCAL\Administrator]    Item Vm F "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmx"

2020-07-07T18:45:51.203Z info hostd[2100000] [Originator@6876 sub=Vimsvc.TaskManager opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] Task Created : haTask--vim.host.LowLevelProvisioningManager.createVm-92202

2020-07-07T18:45:51.204Z info hostd[2100005] [Originator@6876 sub=Vmsvc opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] Creating VM on legacy datastore ([]/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmx)

2020-07-07T18:45:51.204Z info hostd[2100005] [Originator@6876 sub=Vmsvc opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] Create VM initiated [21]: /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmx

2020-07-07T18:45:51.205Z info hostd[2100005] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] FILE: FileCreateDirectoryEx: Failed to create /vmfs. Error = 17

2020-07-07T18:45:51.205Z info hostd[2100005] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] FILE: FileCreateDirectoryEx: Failed to create /vmfs/volumes. Error = 17

2020-07-07T18:45:51.205Z info hostd[2100005] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] FILE: FileCreateDirectoryEx: Failed to create /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe. Error = 17

2020-07-07T18:45:51.205Z info hostd[2100005] [Originator@6876 sub=Libs opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] FILE: FileCreateDirectoryEx: Failed to create /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028. Error = 17

2020-07-07T18:45:51.214Z info hostd[2100005] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmx opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] SetVmxVersion: switching environment browser to vmx version 'vmx-14'

2020-07-07T18:45:51.220Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-DSCPTR:/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk: Cannot open disk descriptor "DescriptorOpenInt" because it is an empty file. This could be due to a buggy s/xvmotion workflow.

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-LINK  : "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk" : failed to open (The file specified is not a virtual disk).

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-CHAIN : "/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk" : failed to open (The file specified is not a virtual disk).

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-LIB   : Failed to open '/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk' with flags 0x1 The file specified is not a virtual disk (15).

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-DSCPTR:/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk: Cannot open disk descriptor "DescriptorOpenInt" because it is an empty file. This could be due to a buggy s/xvmotion workflow.

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-LINK  : "/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk" : failed to open (The file specified is not a virtual disk).

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-CHAIN : "/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk" : failed to open (The file specified is not a virtual disk).

2020-07-07T18:45:51.221Z info hostd[2100005] [Originator@6876 sub=DiskLib opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] DISKLIB-LIB   : Failed to open '/vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk' with flags 0x1 The file specified is not a virtual disk (15).

2020-07-07T18:45:51.222Z warning hostd[2100005] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmx opID=kc7n3c1e-13464-auto-ae1-h5:70003941-c8-01-b7-d2ce user=vpxuser:VSPHERE.LOCAL\Administrator] ValidateAddDisk: diskProperties are not loaded, using size from passed disk spec

It seems that there is a problem with creating folder on the destination datastore.

/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe is the destination.

[msripada]

create a test file on that datastore.. check vmkernel.log for same time if the problem is with datastore.. I suspect it could be for a different reason..

[continuum]

>> Failed to open '/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk' with flags 0x1 The file specified is not a virtual disk (15).

Possible reasons:

- bad syntax in descriptorfile

- descriptor does not link to the correct flat.vmdk (spelling issues - bad path ...

- flat.vmdk too small or unreadable

To check in details connect via WinSCP or putty - as datastorebrowser will only show the flat.vmdk when the descriptorfile is bad ...

[mahmn]

I can create folders on the destination datastore via the file manager on vsphere.

This is what I see in vmware.log on the source node:

2020-07-07T15:49:43.229Z| vmx| I125: VigorTransportProcessClientPayload: opID=kc7n3c1e-18315-auto-e4s-h5:70004380-d-01-b8-67b1 seq=202920: Receiving Migrate.PrepareSource request.

2020-07-07T15:49:43.229Z| vmx| I125: MigrateVMXdrToSpec: type: 1 srcIp=<10.1.1.101> dstIp=<10.1.1.103> mid=56086a4b229b932 uuid=00000000-0000-0000-0000-ac1f6b1b6dbe priority=yes checksumMemory=no maxDowntime=0 encrypted=0 resumeDuringPageIn=no latencyAware=yes diskOpFile= srcLogIp=<<unknown>> dstLogIp=<<unknown>> ftPrimaryIp=<<unknown>> ftSecondaryIp=<<unknown>>

2020-07-07T15:49:43.229Z| vmx| I125: MigrateVMXdrToSpec: scsi:0:0 -> /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk, parent:null, parentShared: 0, rdmDevice: null,transform: 2, numSnapshots: 0, policy: 'null'

2020-07-07T15:49:43.229Z| vmx| I125: MigrateVMXdrToSpec: scsi:0:1 -> /vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028_1.vmdk, parent:null, parentShared: 0, rdmDevice: null,transform: 2, numSnapshots: 0, policy: 'null'

2020-07-07T15:49:43.229Z| vmx| I125: MigrateVMXdrToSpec: type 1 unsharedSwap 1 memMinToTransfer 0 cpuMinToTransfer 0 numDisks 2 numStreamIps 1 numFtStreamIps 0

2020-07-07T15:49:43.229Z| vmx| I125: Received migrate 'to' request for mid id 387457609875700018, src ip <10.1.1.101>, dst ip <10.1.1.103>(invalidate source config).

2020-07-07T15:49:43.230Z| vmx| I125: MigrateSetInfo: state=1 srcIp=<10.1.1.101> dstIp=<10.1.1.103> mid=387457609875700018 uuid=00000000-0000-0000-0000-ac1f6b1b6dbe priority=high

2020-07-07T15:49:43.230Z| vmx| I125: MigrateSetState: Transitioning from state 0 to 1.

2020-07-07T15:49:43.230Z| vmx| I125: MigrateReadHostLog: Hostlog_Dump: Hostlog 101.win7.user88.028-30e2b964.hlog

2020-07-07T15:49:43.231Z| vmx| I125:    UUID: 00000000-0000-0000-0000-ac1f6b1b6dc6

2020-07-07T15:49:43.231Z| vmx| I125:    MigID: 387457609875700018

2020-07-07T15:49:43.231Z| vmx| I125:    HLState: none

2020-07-07T15:49:43.231Z| vmx| I125:    ToFrom: none

2020-07-07T15:49:43.231Z| vmx| I125:    MigType: invalid

2020-07-07T15:49:43.231Z| vmx| I125:    OpType: nfc

2020-07-07T15:49:43.231Z| vmx| I125:    WorldID: 0

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/101.win7.user88.028.nvram"

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/vmware-3.log"

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/vmware-2.log"

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/vmware-1.log"

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/vmware-0.log"

2020-07-07T15:49:43.231Z| vmx| I125:    Item File S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/vmware.log"

2020-07-07T15:49:43.231Z| vmx| I125:    Item Vm S "/vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028/101.win7.user88.028.vmx"

2020-07-07T15:49:43.232Z| vmx| I125: VigorTransport_ServerSendResponse opID=kc7n3c1e-18315-auto-e4s-h5:70004380-d-01-b8-67b1 seq=202920: Completed Migrate request.

Please note that the VM has two disks. The OS is on the SSD and the user files are on an HDD. Both source and destination have SSD and HDD. I also have configured vMotion to move SSD to SSD and HDD to HDD as below

Source:

HDD: /vmfs/volumes/5d9c9c49-dd68fb8e-97b0-ac1f6b1b6dc6/101.win7.user88.028

SSD: /vmfs/volumes/5d988136-0e8cb0e5-8c72-ac1f6b1b6dc6/101.win7.user88.028

Destination:

HDD: /vmfs/volumes/5da1b492-09196285-5470-ac1f6b1b6dbe/101.win7.user88.028

SSD: /vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028

[continuum]

This vmdk is on top of your todo list:

'/vmfs/volumes/5d98b77b-7e08dd43-81c1-ac1f6b1b6dbe/101.win7.user88.028/101.win7.user88.028.vmdk'

Is the descriptor vmdk ok ?

is the flat.vmdk large enough ?

is the flat.vmdk readable with hexdump for example ?

I see this is the destination vmdk ...

Is the directory writeable ? - is there enough free space ?

do any related messages appear in vmkernel.kog ? - eventually indicating issues with the destination vmfs ?

[mahmn]

Bingo.... I turned off the VM and did the same procedure and it is now migrating. It is slow but haven't seen any error yet (now 75%).

Don't know what can make difference between a powered off VM and powered on VM...