vMotion fails at 14% with the error: Timed out waiting for migration start request
search cancel

vMotion fails at 14% with the error: Timed out waiting for migration start request

book

Article ID: 320021

calendar_today

Updated On:

Products

VMware

Issue/Introduction

Symptoms:
  • Performing a vMotion of a virtual machine fails with the errors:

    Timed out waiting for migration start request

    The operation is not allowed in the current state

  • In the hostd.log file, located at /var/log/, you see entries similar to:

    YYYY-MM-DDT18:05:57.413Z [3E057B90 info 'vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Disconnect check in progress.
    YYYY-MM-DDT18:05:57.413Z [3DF03B90 verbose 'Vmsvc.vm://vmfs/volumes/datastorename/VM1/VM1.vmx'] VMotionLastStatusCb: Failed with error 4: Timed out waiting for migration start request.

    YYYY-MM-DDT18:05:57.424Z [3DF03B90 info 'Hostsvc.HaHost'] vmxSwapEnabled = true vmmOvhd.anonymous: 22964 vmmOvhd.paged: 63957 vmmOvhd.nonpaged: 13771
    YYYY-MM-DDT18:05:57.424Z [3DF03B90 info 'Hostsvc.HaHost'] vmkOvhd.fixd = 303104 vmkOvhd.variable: 2050 vmkOvhd.selfSwap: 3145728
    YYYY-MM-DDT18:05:57.424Z [3DF03B90 info 'Hostsvc.HaHost'] Computed from lib overhead: 150466560 for (memPages: 524288, fbSize: 2048, #vcpus: 2, #lsiscsi: 1, #pvscsi: 0, #passthru: 0, #network: 1) vmkOverhead: 7647232
    YYYY-MM-DDT18:05:57.424Z [3DF03B90 info 'Hostsvc.HaHost'] overhead result (no CBRC): 158113792
    YYYY-MM-DDT18:05:57.424Z [3DF03B90 info 'Hostsvc.HaHost'] Predicted overhead: 158113792 for (memory: 2147483648, video: 8388608, #vcpus: 2, autodetect: false, enable3D: false, svgaPtFbSize: 8388608, cbrcOverhead: 0
    YYYY-MM-DDT18:05:57.424Z [3DF03B90 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Time to gather config: 11 (msecs)
    YYYY-MM-DDT18:05:57.425Z [3DF44B90 verbose 'Hbrsvc'] Replicator: ReconfigListener triggered for config VM 44
    YYYY-MM-DDT18:05:57.431Z [3DF03B90 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] VMotionLastStatusCb:: hostlog state changed from emigrating to failure
    YYYY-MM-DDT18:05:57.431Z [3DF03B90 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] VMotionResolveCheck: Operation in progress
    YYYY-MM-DDT18:05:57.431Z [3DF44B90 verbose 'Hbrsvc'] Replicator: VmReconfig ignoring VM 44 not configured for replication
    YYYY-MM-DDT18:05:57.432Z [3DF44B90 info 'Snmpsvc'] VmConfigListener: vm state change received, queueing reload request
    YYYY-MM-DDT18:05:57.433Z [3E1DCB90 warning 'Default'] Can't convert IP Address of type 0
    YYYY-MM-DDT18:05:57.433Z [3DF03B90 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] VMotionStatusCb: Completed
    YYYY-MM-DDT18:05:57.433Z [3DF03B90 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] VMotionResolveCheck: Firing ResolveCb
    YYYY-MM-DDT18:05:57.433Z [3DF03B90 info 'Vcsvc.VMotionSrc (1388772268136447)'] ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION
    YYYY-MM-DDT18:05:57.433Z [3DF03B90 info 'Vcsvc.VMotionSrc (1388772268136447)'] ResolveCb: Failed with fault: (vmodl.fault.SystemError) {
    dynamicType = <unset>,
    faultCause = (vmodl.MethodFault) null,
    reason = "Timed out waiting for migration start request.
    ",
    msg = "",
    }

  • In the hostd.log file, located at /var/log/, you see entries similar to:

    YYYY-MM-DDT18:04:27.536Z [4FA40B70 info 'Vcsvc.VMotion' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] InitiateDestination [1388772268136447], VM = '/vmfs/volumes/datastorename/VM1/VM1.vmx'
    YYYY-MM-DDT18:04:27.536Z [4FA40B70 info 'Vimsvc.TaskManager' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Task Created : haTask-ha-folder-vm-vim.Folder.registerVm-95992205
    YYYY-MM-DDT18:04:27.536Z [4FA40B70 info 'Solo.HaVMFolder' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Register called: []/vmfs/volumes/datastorename/VM1/VM1.vmx
    YYYY-MM-DDT18:04:27.544Z [4E040B70 verbose 'Default' opID=9348D6C9-0000017D user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
    YYYY-MM-DDT18:04:27.647Z [4FA40B70 verbose 'Vmsvc' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Queued registering virtual machine /vmfs/volumes/datastorename/VM1/VM1.vmx
    YYYY-MM-DDT18:04:27.647Z [4E040B70 verbose 'Vmsvc'] Initializing registering virtual machine [51]: /vmfs/volumes/datastorename/VM1/VM1.vmx

    YYYY-MM-DDT18:04:27.650Z [4E040B70 info 'vm:Vix: [34103 foundryPollWorker.c:624]: FoundryPollWorker_AssignVMToWorker: Assign VM:/vmfs/volumes/datastorename/VM1/VM1.vmx'] to worker 4E640B70.
    YYYY-MM-DDT18:04:27.653Z [4E640B70 info 'vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Reloading config state.
    YYYY-MM-DDT18:04:27.668Z [4E640B70 info 'Libs'] VMHS: Transitioned vmx/execState/val to poweredOff
    YYYY-MM-DDT18:04:27.693Z [4E040B70 verbose 'Default'] SetVmHandle /vmfs/volumes/datastorename/VM1/VM1.vmx 3145898
    YYYY-MM-DDT18:04:27.693Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Upgrade is required for virtual machine, version: 7
    YYYY-MM-DDT18:04:27.694Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Snapshot tree refresh ignored because the disk access is not enabled.
    YYYY-MM-DDT18:04:27.695Z [4E040B70 warning 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] PopulateCache failed: _diskAccess : false, _storageAccessible : true
    YYYY-MM-DDT18:04:27.696Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Get shared vigor fields translated error to vim.fault.GenericVmConfigFault
    YYYY-MM-DDT18:04:27.696Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Get shared vigor fields failed: vim.fault.GenericVmConfigFault
    YYYY-MM-DDT18:04:27.696Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Get shared vigor fields message: CPUID register value () is invalid.

    CPUID register value () is invalid.
    CPUID register value () is invalid.
    CPUID register value () is invalid.
    YYYY-MM-DDT18:04:27.696Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Error encountered while retrieving configuration. Marking configuration as invalid: vim.fault.GenericVmConfigFault
    YYYY-MM-DDT18:04:27.696Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Fault Tolerance state callback received
    YYYY-MM-DDT18:04:27.696Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Record/replay state callback received
    YYYY-MM-DDT18:04:27.696Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Skipped tools version initialization as the VM's disk access is not enabled
    YYYY-MM-DDT18:04:27.697Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] State Transition (VM_STATE_INITIALIZING -> VM_STATE_OFF)
    YYYY-MM-DDT18:04:27.697Z [4E040B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Max connection count changed from 0 to 40
    YYYY-MM-DDT18:04:27.698Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Initialized virtual machine.
    YYYY-MM-DDT18:04:27.701Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] Marking VirtualMachine invalid
    YYYY-MM-DDT18:04:27.701Z [4E040B70 info 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx'] State Transition (VM_STATE_OFF -> VM_STATE_INVALID_CONFIG)
    YYYY-MM-DDT18:04:27.701Z [4E040B70 verbose 'Hostsvc.HostConfigSyncManagerImpl'] Sync called
    YYYY-MM-DDT18:04:27.701Z [4E040B70 verbose 'Hostsvc.HostConfigSyncManagerImpl'] Scheduling '/sbin/backup.sh' in 5 seconds (backup counter = 0)
    YYYY-MM-DDT18:04:27.702Z [4E040B70 verbose 'Hostsvc.ResourcePool ha-root-pool'] Added child 51 to pool
    YYYY-MM-DDT18:04:27.702Z [4E040B70 info 'Vimsvc.ha-eventmgr'] Event 250 : Registered Unknown 36 on mtaspesx4.mta.mdot.mdstate in ha-datacenter
    YYYY-MM-DDT18:04:27.702Z [4E040B70 warning 'Default'] Complete Task: task haTask-ha-folder-vm-vim.Folder.registerVm-95992205 not registered as started
    YYYY-MM-DDT18:04:27.702Z [4E040B70 info 'Vimsvc.TaskManager'] Task Completed : haTask-ha-folder-vm-vim.Folder.registerVm-95992205 Status success
    YYYY-MM-DDT18:04:27.708Z [FFD5BB70 verbose 'Default' opID=9348D6C9-0000017E user=root] AdapterServer: target='vmodl.query.PropertyCollector:session[43831e05-bc42-7082-620c-a24c0da54260]5268e62e-6cca-eab7-117e-ea9b8e05dd4a', method='waitForUpdates'
    YYYY-MM-DDT18:04:27.710Z [4F780B70 verbose 'Default' opID=SWI-bfd8bde9 user=vpxuser] AdapterServer: target='vim.ResourcePool:ha-root-pool', method='GetConfig'
    YYYY-MM-DDT18:04:27.712Z [4E040B70 verbose 'Default' opID=SWI-bfd8bde9 user=vpxuser] AdapterServer: target='vim.ResourcePool:ha-root-pool', method='GetName'
    YYYY-MM-DDT18:04:27.748Z [4FA40B70 error 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Invalid transition requested (VM_STATE_INVALID_CONFIG -> VM_STATE_IMMIGRATING): Invalid state
    YYYY-MM-DDT18:04:27.748Z [4FA40B70 warning 'Vcsvc.VMotionDst (1388772268136447)' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Bind: Failed to initialize VMotionWorker
    YYYY-MM-DDT18:04:27.748Z [4FA40B70 warning 'Vcsvc.VMotionDst (1388772268136447)' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Initiate: Bind failed: vim.fault.InvalidState
    YYYY-MM-DDT18:04:27.748Z [4FA40B70 warning 'Vcsvc.VMotionDst (1388772268136447)' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Initiate: Unregistering after Bind failure
    YYYY-MM-DDT18:04:27.748Z [4FA40B70 verbose 'Vmsvc.vm:/vmfs/volumes/datastorename/VM1/VM1.vmx' opID=57C757C9-000004C9-9c-75-89 user=vpxuser] Unregister called on virtual machine



Cause

This issue occurs because there are missing cpuid values in the .vmx file located on the virtual machine being vMotioned.

Resolution

This issue is resolved in ESXi 5.5 Update 2, available at VMware Downloads. For more information, see VMware ESXi 5.5 Update 2 Release Notes.

To work around the issue:
  1. Make a backup of the .vmx file cp path/filename path/filename.bak.

    Where path is the full path of the file and filename is the name of the file you wish to edit.

    Note: Ensure the second parameter in the cp command has a filename with the .bak extension to indicate that it is a backup copy.

  2. Locate the cpuid entries in the .vmx file with blank values. For example:

    cpuid.X.eax = ""
    cpuid.X.ecx = ""
    cpuid.X.ecx.amd = ""
    cpuid.X.edx = ""


    Note: An X represents a possible numerical value.

  3. Power off the machine.
  4. With a text editor, remove these entries from the .vmx file. For more information, see Editing files on an ESX host using vi or nano (1020302).
  5. Reload the virtual machine. For more information, see Reloading a vmx file without removing the virtual machine from inventory (1026043). Alternatively, unregister and re-register the machine.
  6. Power on the virtual machine.
  7. Confirm that the entries for the cpuid have been removed from the .vmx file.
  8. Perform the vMotion again on the powered on machine.


Additional Information


Editing configuration files in VMware ESXi and ESX
Editing files on an ESX host using vi or nano
Reloading a vmx file without removing the virtual machine from inventory
vMotion が 14% の時点で失敗し、次のエラーが表示される: 移行開始要求の待機中にタイム アウトになりました
vMotion 在进行到 14% 时失败,并出现错误:等待迁移启动请求时超时

Impact/Risks:
  • The virtual machine must be powered off to commit the changes to the .vmx file.
  • You can power the machine off and cold migrate it, but future vMotions fail if the changes are not made to the file.
  • Simply editing the file and reloading the virtual machine without powering it off causes the blank entries to be repopulated into the .vmx file once it is reloaded.
  • The .vmx file must be edited to allow future migrations to succeed and it must be powered off temporarily for the change to take effect.