VMware Horizon Community
ZellOr
Enthusiast
Enthusiast
‎10-08-2018 11:01 AM

"Failed to receive migration/Unable to prepare migration" during the creation of new VMs

Hello everybody,

we have a problem with our Horizon 7.6.0 environment. During the creation of new VMs in a instant-clone desktop pool, some VMs repeatedly fail with the following error messages:

"08.10.2018 07:49:50 MESZ: Cloning of VM XXX has failed: Fault type is VC_FAULT_FATAL - Failed to receive migration."

or

"08.10.2018 07:55:56 MESZ: Cloning of VM XXX has failed: Fault type is VC_FAULT_FATAL - Unable to prepare migration."

Does anyone have any idea why this is happening?

0 Kudos
1 Reply
Kaffeeknecht
Contributor
Contributor
‎11-12-2018 04:38 AM

vmkernel.log of a failed instant-clone Operation:

2018-11-12T12:31:01.436Z cpu3:19624853 opID=b6001e8d)World: 11942: VC opID 748b8564-01-5a-0a8f maps to vmkernel opID b6001e8d

2018-11-12T12:31:01.436Z cpu3:19624853 opID=b6001e8d)LVM: 12674: LVMProbeDevice failed with status "Device does not contain a logical volume".

2018-11-12T12:31:01.497Z cpu1:19624853 opID=b6001e8d)FS3: 183: <START fbb>

2018-11-12T12:31:01.497Z cpu1:19624853 opID=b6001e8d)261120 resources, each of size 0

2018-11-12T12:31:01.497Z cpu1:19624853 opID=b6001e8d)Organized as 21 CGs, 64 C/CG and 200 R/C

2018-11-12T12:31:01.497Z cpu1:19624853 opID=b6001e8d)CGsize 65536. 0th CG at 65536.

2018-11-12T12:31:01.497Z cpu1:19624853 opID=b6001e8d)FS3: 185: <END fbb>

2018-11-12T12:31:01.636Z cpu0:19624853 opID=b6001e8d)FS3: 183: <START fdc>

2018-11-12T12:31:01.637Z cpu0:19624853 opID=b6001e8d)130000 resources, each of size 2048

2018-11-12T12:31:01.637Z cpu0:19624853 opID=b6001e8d)Organized as 11 CGs, 64 C/CG and 200 R/C

2018-11-12T12:31:01.637Z cpu0:19624853 opID=b6001e8d)CGsize 26279936. 0th CG at 65536.

2018-11-12T12:31:01.637Z cpu0:19624853 opID=b6001e8d)FS3: 185: <END fdc>

2018-11-12T12:31:01.779Z cpu0:19624853 opID=b6001e8d)FS3: 183: <START pbc>

2018-11-12T12:31:01.779Z cpu0:19624853 opID=b6001e8d)64512 resources, each of size 4096

2018-11-12T12:31:01.779Z cpu0:19624853 opID=b6001e8d)Organized as 63 CGs, 64 C/CG and 16 R/C

2018-11-12T12:31:01.779Z cpu0:19624853 opID=b6001e8d)CGsize 4259840. 0th CG at 65536.

2018-11-12T12:31:01.779Z cpu0:19624853 opID=b6001e8d)FS3: 185: <END pbc>

2018-11-12T12:31:01.957Z cpu0:19624853 opID=b6001e8d)FS3: 183: <START sbc>

2018-11-12T12:31:01.957Z cpu0:19624853 opID=b6001e8d)32000 resources, each of size 8192

2018-11-12T12:31:01.957Z cpu0:19624853 opID=b6001e8d)Organized as 8 CGs, 64 C/CG and 64 R/C

2018-11-12T12:31:01.957Z cpu0:19624853 opID=b6001e8d)CGsize 33619968. 0th CG at 65536.

2018-11-12T12:31:01.957Z cpu0:19624853 opID=b6001e8d)FS3: 185: <END sbc>

2018-11-12T12:31:02.081Z cpu1:19624853 opID=b6001e8d)FS3: 183: <START pb2>

2018-11-12T12:31:02.081Z cpu1:19624853 opID=b6001e8d)256 resources, each of size 4096

2018-11-12T12:31:02.081Z cpu1:19624853 opID=b6001e8d)Organized as 1 CGs, 64 C/CG and 16 R/C

2018-11-12T12:31:02.081Z cpu1:19624853 opID=b6001e8d)CGsize 4259840. 0th CG at 65536.

2018-11-12T12:31:02.081Z cpu1:19624853 opID=b6001e8d)FS3: 185: <END pb2>

2018-11-12T12:31:02.238Z cpu1:19624853 opID=b6001e8d)Res3: 6850: SDDir: type: 0x5, fileLength: 0x118, numBlocks: 1

2018-11-12T12:31:02.247Z cpu1:19624853 opID=b6001e8d)Vol3: 1286: Created VMFS-5.81 with config 0x16 on vol '8572e95b-348d-99e7-cdfb-ecf4bbeda668'

2018-11-12T12:31:02.269Z cpu1:19624853 opID=b6001e8d)osfs: DebugDumpVmklinkResponse:787: {ID: c273f; type:LOOKUP; pid:[    vsan]; cid:52a6cfb29aeafb61-41f70467b04ed071; status:Not ready; bufLen:0;

2018-11-12T12:31:02.269Z cpu1:19624853 opID=b6001e8d)osfs: OSFS_VmklinkLookup:492: Failure (p [    vsan], c 52a6cfb29aeafb61-41f70467b04ed071)

2018-11-12T12:31:02.269Z cpu1:19624853 opID=b6001e8d)osfs: OSFS_Lookup:2666: Lookup error: file = FLP-M-021, status = Not ready

2018-11-12T12:31:02.271Z cpu1:19624853 opID=b6001e8d)osfs: DebugDumpVmklinkResponse:787: {ID: c2740; type:LOOKUP; pid:[    vsan]; cid:52a6cfb29aeafb61-41f70467b04ed071; status:Not ready; bufLen:0;

2018-11-12T12:31:02.271Z cpu1:19624853 opID=b6001e8d)osfs: OSFS_VmklinkLookup:492: Failure (p [    vsan], c 52a6cfb29aeafb61-41f70467b04ed071)

2018-11-12T12:31:02.271Z cpu1:19624853 opID=b6001e8d)osfs: OSFS_Lookup:2666: Lookup error: file = FLP-M-021, status = Not ready

2018-11-12T12:31:02.327Z cpu0:2101618)Vol3: 1072: Unable to register file system 8572e95b-348d-99e7-cdfb-ecf4bbeda668 for APD timeout notifications: Inappropriate ioctl for device

2018-11-12T12:31:03.018Z cpu0:2101212 opID=947d1bff)World: 11942: VC opID 748b8564-01-7f-0ac8 maps to vmkernel opID 947d1bff

2018-11-12T12:31:03.018Z cpu0:2101212 opID=947d1bff)Config: 703: "SIOControlFlag2" = 1, Old Value: 0, (Status: 0x0)

2018-11-12T12:31:03.063Z cpu0:19624861)MemSched: vm 19624861: 5745: extended swap to 28160 pgs

2018-11-12T12:31:05.028Z cpu20:19624861 opID=0)World: vm 19624866: 7075: Starting world vmm0:FLP-M-021 of type 8

2018-11-12T12:31:05.028Z cpu20:19624861 opID=0)Sched: vm 19624866: 6193: Adding world 'vmm0:FLP-M-021', group 'host/user', cpu: shares=-3 min=0 minLimit=-1 max=-1, mem: shares=-3 min=1835008 minLimit=-1 max=-1

2018-11-12T12:31:05.028Z cpu20:19624861 opID=0)Sched: vm 19624866: 6208: renamed group 127210854 to vm.19624861

2018-11-12T12:31:05.028Z cpu20:19624861 opID=0)Sched: vm 19624866: 6225: group 127210854 is located under group 4

2018-11-12T12:31:05.099Z cpu22:19624861 opID=0)World: vm 19624871: 7075: Starting world vmm1:FLP-M-021 of type 8

2018-11-12T12:31:05.144Z cpu22:19624861 opID=0)Migrate: vm 19624866: 4082: Setting INSTANT_CLONE info: Dest ts = 2972998797614803058, src ip = <127.0.0.1> dest ip = <127.0.0.1> Dest wid = 0 using UNSHARED swap, unencrypted

2018-11-12T12:31:05.144Z cpu22:19624861 opID=0)InstantClone: 644: 2972998797614803058 😧 Starting Instant Clone migration 2972998797614803058 with leader 19624866

2018-11-12T12:31:05.144Z cpu22:19624861 opID=0)Hbr: 3588: Migration start received (worldID=19624866) (migrateType=7) (event=0) (isSource=0) (sharedConfig=0)

2018-11-12T12:31:05.172Z cpu1:2101217 opID=53971e1c)World: 11942: VC opID 748b8564-01-d7-0acf maps to vmkernel opID 53971e1c

2018-11-12T12:31:05.172Z cpu1:2101217 opID=53971e1c)Config: 703: "SIOControlFlag2" = 2, Old Value: 1, (Status: 0x0)

2018-11-12T12:31:05.291Z cpu11:8336585)Migrate: vm 8336586: 4082: Setting INSTANT_CLONE info: Source ts = 2972998797614803058, src ip = <127.0.0.1> dest ip = <127.0.0.1> Dest wid = 19624866 using UNSHARED swap, unencrypted

2018-11-12T12:31:05.292Z cpu11:8336585)InstantClone: 644: 2972998797614803058 S: Starting Instant Clone migration 2972998797614803058 with leader 8336586

2018-11-12T12:31:05.294Z cpu11:8336585)Hbr: 3588: Migration start received (worldID=8336586) (migrateType=7) (event=0) (isSource=1) (sharedConfig=0)

2018-11-12T12:31:05.298Z cpu14:8336599 opID=0)VSCSI: 6602: handle 12395(vscsi0:0):Destroying Device for world 8336586 (pendCom 0)

2018-11-12T12:31:05.721Z cpu14:8336599 opID=0)InstantClone: 1171: 2972998797614803058 S: Checkpoint finished.

2018-11-12T12:31:05.741Z cpu14:8336599 opID=0)InstantClone: 1210: 2972998797614803058 S: Ready for destination restore!

2018-11-12T12:31:05.759Z cpu3:19624861)WARNING: Migrate: 6267: 2972998797614803058 😧 Migration considered a failure by the VMX.  It is most likely a timeout, but check the VMX log for the true error.

2018-11-12T12:31:05.759Z cpu3:19624861)WARNING: Migrate: 282: 2972998797614803058 😧 Failed: Migration determined a failure by the VMX (0xbad0092) @0x41803679ed3e

2018-11-12T12:31:05.759Z cpu3:19624861)WARNING: Migrate: 282: 2972998797614803058 S: Failed: Migration determined a failure by the VMX (0xbad0092) @0x4180383709b2

2018-11-12T12:31:05.759Z cpu3:19624861)Hbr: 3682: Migration end received (worldID=19624866) (migrateType=7) (event=1) (isSource=0) (sharedConfig=0)

2018-11-12T12:31:05.778Z cpu1:8336585)WARNING: Migrate: 6267: 2972998797614803058 S: Migration considered a failure by the VMX.  It is most likely a timeout, but check the VMX log for the true error.

2018-11-12T12:31:06.004Z cpu8:8336599 opID=0)VSCSI: 3782: handle 12396(vscsi0:0):Using sync mode due to sparse disks

2018-11-12T12:31:06.004Z cpu8:8336599 opID=0)VSCSI: 3810: handle 12396(vscsi0:0):Creating Virtual Device for world 8336586 (FSS handle 511193286) numBlocks=125829120 (bs=512)

2018-11-12T12:31:06.009Z cpu8:8336599 opID=0)cbrc_filter: CBRC_DigestLoad:3170: Loading digest with ID 306c 306c

2018-11-12T12:31:06.015Z cpu8:8336599 opID=0)VSCSI: 273: handle 12396(vscsi0:0):Input values: res=0 limit=-2 bw=-1 Shares=1000

2018-11-12T12:31:06.016Z cpu8:8336599 opID=0)Vmxnet3: 18168: Disable Rx queuing; queue size 512 is larger than Vmxnet3RxQueueLimit limit of 64.

2018-11-12T12:31:06.016Z cpu8:8336599 opID=0)Vmxnet3: 18310: indLROPktToGuest: 1, vcd->umkShared->vrrsSelected: 3 port 0x3000229

2018-11-12T12:31:06.016Z cpu8:8336599 opID=0)Vmxnet3: 18552: Using default queue delivery for vmxnet3 for port 0x3000229

2018-11-12T12:31:06.017Z cpu8:8336599 opID=0)Hbr: 3682: Migration end received (worldID=8336586) (migrateType=7) (event=1) (isSource=1) (sharedConfig=0)

2018-11-12T12:31:06.159Z cpu11:2102883)Config: 703: "SIOControlFlag2" = 1, Old Value: 2, (Status: 0x0)

2018-11-12T12:31:06.182Z cpu1:2985220)Config: 703: "SIOControlFlag2" = 0, Old Value: 1, (Status: 0x0)

2018-11-12T12:31:06.642Z cpu11:6212316 opID=0)osfs: OSFS_Rmdir:374: Failed rmdir pid:[    vsan], cid:52a6cfb29aeafb61-41f70467b04ed071, child:8572e95b-348d-99e7-cdfb-ecf4bbeda668, status: Not supported

2018-11-12T12:31:22.296Z cpu9:2101217)WARNING: com.vmware.vmklinkmpi: VmklinkMPI_CallSync:1303: No response received for message 0xc2741 on osfs-vmklink (wait status Timeout)

2018-11-12T12:31:22.296Z cpu9:2101217)osfs: OSFSVmklinkCall:231: vmklink call failed with: Timeout

2018-11-12T12:31:22.296Z cpu9:2101217)osfs: OSFS_VmklinkLookup:479: Error making Lookup VmklinkCall

2018-11-12T12:31:22.296Z cpu9:2101217)osfs: OSFS_Lookup:2666: Lookup error: file = 8572e95b-348d-99e7-cdfb-ecf4bbeda668, status = Timeout

2018-11-12T12:31:22.387Z cpu0:19624852)WARNING: VSAN: VsanIoctlCtrlNodeCommon:2522: 8572e95b-348d-99e7-cdfb-ecf4bbeda668: RPC to DOM returned: No connection

2018-11-12T12:31:22.390Z cpu9:19624852)WARNING: VSAN: VsanIoctlCtrlNodeCommon:2522: 8572e95b-348d-99e7-cdfb-ecf4bbeda668: RPC to DOM returned: No connection

2018-11-12T12:31:24.391Z cpu1:19624852)WARNING: VSAN: Vsan_GetObjCapCB:486: Failed to get attributes for object 8572e95b-348d-99e7-cdfb-ecf4bbeda668 : Not found

2018-11-12T12:31:26.393Z cpu0:19624852)WARNING: VSAN: Vsan_GetObjCapCB:486: Failed to get attributes for object 8572e95b-348d-99e7-cdfb-ecf4bbeda668 : Not found

2018-11-12T12:31:26.393Z cpu0:19624852)Vol3: 1132: Couldn't read volume header from : No connection

2018-11-12T12:31:28.394Z cpu0:19624852)WARNING: VSAN: Vsan_GetObjCapCB:486: Failed to get attributes for object 8572e95b-348d-99e7-cdfb-ecf4bbeda668 : Not found

2018-11-12T12:31:28.394Z cpu0:19624852)Vol3: 1132: Couldn't read volume header from : No connection

2018-11-12T12:31:30.396Z cpu3:19624852)WARNING: VSAN: Vsan_GetObjCapCB:486: Failed to get attributes for object 8572e95b-348d-99e7-cdfb-ecf4bbeda668 : Not found

2018-11-12T12:31:30.396Z cpu3:19624852)Vol3: 1132: Couldn't read volume header from : No connection

2018-11-12T12:31:32.397Z cpu1:19624852)WARNING: VSAN: Vsan_GetObjCapCB:486: Failed to get attributes for object 8572e95b-348d-99e7-cdfb-ecf4bbeda668 : Not found

2018-11-12T12:31:32.397Z cpu9:19624852)Vol3: 1132: Couldn't read volume header from : No connection

2018-11-12T12:31:32.397Z cpu9:19624852)osfs: OSFS_MountChild:4027: Failed to probe OSFS child for device name '8572e95b-348d-99e7-cdfb-ecf4bbeda668': No filesystem on the device

2018-11-12T12:31:32.398Z cpu9:2100243)WARNING: com.vmware.vmklinkmpi: VmklinkMPIMsgRecv:413: [osfs-vmklink] : No slot found for receive (ID: 0xc2741)

2018-11-12T12:31:32.398Z cpu9:2100243)WARNING: com.vmware.vmklinkmpi: VmklinkMPICallback:615: [osfs-vmklink] : discarding user reply for message c2741 (no request waiting)

0 Kudos