search

apache / cloudstack

Apache CloudStack is an opensource Infrastructure as a Service (IaaS) cloud computing platform
https://cloudstack.apache.org/
Apache License 2.0
1.99k stars 1.09k forks source link

Unable to Boot VM in UEFI mode (KVM) #5754

Closed levindecaro closed 2 years ago

levindecaro commented 2 years ago
ISSUE TYPE
COMPONENT NAME
Guest VM Deployment
UEFI
CLOUDSTACK VERSION
4.16.0
CONFIGURATION

N/A

OS / ENVIRONMENT

CentOS Linux release 7.9.2009 qemu-kvm-common-ev-2.12.0-44.1.el7_8.1.x86_64 qemu-kvm-ev-2.12.0-44.1.el7_8.1.x86_64 OVMF-20180508-6.gitee3198e672e2.el7.noarch

SUMMARY

Cannot boot VM into UEFI mode, always fallback into BIOS mode.

STEPS TO REPRODUCE
Launch a VM either choosing UEFI LEGACY/SECURE via UI or start existing UEFI enabled VM.
EXPECTED RESULTS
VM should start in UEFI mode.
ACTUAL RESULTS
VM booted into BIOS mode.

Result xml as below.
<domain type='kvm' id='238'>
  <name>i-2-2934-VM</name>
  <uuid>8c00e797-c713-4f4e-9a24-12c3436cf06f</uuid>
  <description>Windows Server 2019 (64-bit)</description>
  <memory unit='KiB'>4194304</memory>
  <currentMemory unit='KiB'>4194304</currentMemory>
  <vcpu placement='static'>2</vcpu>
  <cputune>
    <shares>250</shares>
  </cputune>
  <resource>
    <partition>/machine</partition>
  </resource>
  <sysinfo type='smbios'>
    <system>
      <entry name='manufacturer'>Apache Software Foundation</entry>
      <entry name='product'>CloudStack KVM Hypervisor</entry>
      <entry name='uuid'>8c00e797-c713-4f4e-9a24-12c3436cf06f</entry>
    </system>
  </sysinfo>
  <os>
    <type arch='x86_64' machine='pc-q35-rhel7.6.0'>hvm</type>
    <boot dev='cdrom'/>
    <boot dev='hd'/>
    <smbios mode='sysinfo'/>
  </os>
  <features>
    <acpi/>
    <apic/>
    <pae/>
  </features>
  <cpu mode='host-passthrough' check='none'>
    <feature policy='require' name='vmx'/>
  </cpu>
  <clock offset='localtime'>
    <timer name='hypervclock' present='yes'/>
  </clock>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <emulator>/usr/libexec/qemu-kvm</emulator>
    <disk type='file' device='disk'>
      <driver name='qemu' type='qcow2' cache='none'/>
      <source file='/cloudstack/sg1/2d837256-b367-4c00-9ce5-f91d963e8ef5'/>
      <backingStore/>
      <target dev='sda' bus='sata'/>
      <serial>2d837256b3674c009ce5</serial>
      <alias name='sata0-0-0'/>
      <address type='drive' controller='0' bus='0' target='0' unit='0'/>
    </disk>
    <disk type='file' device='cdrom'>
      <driver name='qemu'/>
      <target dev='sdd' bus='sata'/>
      <readonly/>
      <alias name='sata0-0-3'/>
      <address type='drive' controller='0' bus='0' target='0' unit='3'/>
    </disk>
    <controller type='usb' index='0' model='qemu-xhci'>
      <alias name='usb'/>
      <address type='pci' domain='0x0000' bus='0x03' slot='0x00' function='0x0'/>
    </controller>
    <controller type='sata' index='0'>
      <alias name='ide'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x1f' function='0x2'/>
    </controller>
    <controller type='pci' index='0' model='pcie-root'>
      <alias name='pcie.0'/>
    </controller>
    <controller type='virtio-serial' index='0'>
      <alias name='virtio-serial0'/>
      <address type='pci' domain='0x0000' bus='0x04' slot='0x00' function='0x0'/>
    </controller>
    <controller type='pci' index='1' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='1' port='0x10'/>
      <alias name='pci.1'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0' multifunction='on'/>
    </controller>
    <controller type='pci' index='2' model='pcie-to-pci-bridge'>
      <model name='pcie-pci-bridge'/>
      <alias name='pci.2'/>
      <address type='pci' domain='0x0000' bus='0x01' slot='0x00' function='0x0'/>
    </controller>
    <controller type='pci' index='3' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='3' port='0x11'/>
      <alias name='pci.3'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x1'/>
    </controller>
    <controller type='pci' index='4' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='4' port='0x12'/>
      <alias name='pci.4'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x2'/>
    </controller>
    <controller type='pci' index='5' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='5' port='0x13'/>
      <alias name='pci.5'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x3'/>
    </controller>
    <controller type='pci' index='6' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='6' port='0x14'/>
      <alias name='pci.6'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x4'/>
    </controller>
    <controller type='pci' index='7' model='pcie-root-port'>
      <model name='pcie-root-port'/>
      <target chassis='7' port='0x15'/>
      <alias name='pci.7'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x5'/>
    </controller>
    <interface type='bridge'>
      <mac address='02:00:33:4c:00:0f'/>
      <source bridge='brvx-3138'/>
      <bandwidth>
        <inbound average='128000' peak='128000'/>
        <outbound average='128000' peak='128000'/>
      </bandwidth>
      <target dev='vnet7'/>
      <model type='e1000'/>
      <link state='up'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x01' function='0x0'/>
    </interface>
    <serial type='pty'>
      <source path='/dev/pts/10'/>
      <target type='isa-serial' port='0'>
        <model name='isa-serial'/>
      </target>
      <alias name='serial0'/>
    </serial>
    <console type='pty' tty='/dev/pts/10'>
      <source path='/dev/pts/10'/>
      <target type='serial' port='0'/>
      <alias name='serial0'/>
    </console>
    <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/i-2-2934-VM.org.qemu.guest_agent.0'/>
      <target type='virtio' name='org.qemu.guest_agent.0' state='disconnected'/>
      <alias name='channel0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
    <input type='tablet' bus='usb'>
      <alias name='input0'/>
      <address type='usb' bus='0' port='1'/>
    </input>
    <input type='mouse' bus='ps2'>
      <alias name='input1'/>
    </input>
    <input type='keyboard' bus='ps2'>
      <alias name='input2'/>
    </input>
    <graphics type='vnc' port='5909' autoport='yes' listen='172.16.0.32'>
      <listen type='address' address='172.16.0.32'/>
    </graphics>
    <video>
      <model type='cirrus' vram='16384' heads='1' primary='yes'/>
      <alias name='video0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x0'/>
    </video>
    <watchdog model='i6300esb' action='none'>
      <alias name='watchdog0'/>
      <address type='pci' domain='0x0000' bus='0x02' slot='0x02' function='0x0'/>
    </watchdog>
    <memballoon model='virtio'>
      <alias name='balloon0'/>
      <address type='pci' domain='0x0000' bus='0x05' slot='0x00' function='0x0'/>
    </memballoon>
    <rng model='virtio'>
      <rate bytes='2048' period='1000'/>
      <backend model='random'>/dev/urandom</backend>
      <alias name='rng0'/>
      <address type='pci' domain='0x0000' bus='0x06' slot='0x00' function='0x0'/>
    </rng>
  </devices>
  <seclabel type='dynamic' model='dac' relabel='yes'>
    <label>+0:+0</label>
    <imagelabel>+0:+0</imagelabel>
  </seclabel>
</domain>

Server Log

2021-12-08 10:03:19,177 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197) (logid:3f3fe7b9) Executing AsyncJobVO {id:42197, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 2934, cmd: org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: {"response":"json","ctxUserId":"2","hostid":"c1fed481-7898-45bb-93ca-347784610714","httpmethod":"GET","ctxStartEventId":"83899","id":"8c00e797-c713-4f4e-9a24-12c3436cf06f","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"8c00e797-c713-4f4e-9a24-12c3436cf06f\",\"interface com.cloud.host.Host\":\"c1fed481-7898-45bb-93ca-347784610714\"}","ctxAccountId":"2","uuid":"8c00e797-c713-4f4e-9a24-12c3436cf06f","cmdEventType":"VM.START"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90520735245649, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
2021-12-08 10:03:19,224 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:19,228 DEBUG [c.c.n.NetworkModelImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:19,230 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Destination Host to deploy the VM is specified, specifying a deployment plan to deploy the VM
2021-12-08 10:03:19,236 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Host: 56 has cpu capability (cpu:56, speed:2500) to support requested CPU: 2 and requested speed: 1500
2021-12-08 10:03:19,237 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Checking if host: 56 has enough capacity for requested CPU: 3000 and requested RAM: (4.00 GB) 4294967296 , cpuOverprovisioningFactor: 12.0
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Hosts's actual total CPU: 140000 and CPU after applying overprovisioning: 1680000
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) considerReservedCapacity isfalse , not considering reserved capacity for calculating free capacity
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Free CPU: 1490000 , Requested CPU: 3000
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Free RAM: (86.43 GB) 92804349952 , Requested RAM: (4.00 GB) 4294967296
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Host has enough CPU and RAM available
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) STATS: Can alloc CPU from host: 56, used: 190000, reserved: 3000, actual total: 140000, total with overprovisioning: 1680000; requested cpu:3000,alloc_from_last_host?:false ,considerReservedCapacity?: false
2021-12-08 10:03:19,241 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) STATS: Can alloc MEM from host: 56, used: (290.25 GB) 311653564416, reserved: (4.00 GB) 4294967296, total: (376.68 GB) 404457914368; requested mem: (4.00 GB) 4294967296, alloc_from_last_host?: false , considerReservedCapacity?: false
2021-12-08 10:03:19,257 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) DeploymentPlanner allocation algorithm: null
2021-12-08 10:03:19,257 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Trying to allocate a host and storage pools from dc:10, pod:10,cluster:7, requested cpu: 3000, requested ram: (4.00 GB) 4294967296
2021-12-08 10:03:19,257 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Is ROOT volume READY (pool already allocated)?: Yes
2021-12-08 10:03:19,264 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 56
2021-12-08 10:03:19,266 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Looking for suitable pools for this host under zone: 10, pod: 10, cluster: 7
2021-12-08 10:03:19,270 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Checking suitable pools for volume (Id, Type): (3621,ROOT)
2021-12-08 10:03:19,270 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Volume has pool already allocated, checking if pool can be reused, poolId: 3
2021-12-08 10:03:19,271 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Planner need not allocate a pool for this volume since its READY
2021-12-08 10:03:19,272 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-12-08 10:03:19,273 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Checking if host: 56 can access any suitable storage pool for volume: ROOT
2021-12-08 10:03:19,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Host: 56 can access pool: 3
2021-12-08 10:03:19,276 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Found a potential host id: 56 name: compute-12.lab.example.com and associated storage pools for this VM
2021-12-08 10:03:19,278 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(10)-Pod(10)-Cluster(7)-Host(56)-Storage()]
2021-12-08 10:03:19,300 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Sync job-42198 execution on object VmWorkJobQueue.2934
2021-12-08 10:03:19,552 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4523:ctx-42fbbdc2) (logid:8f764742) ===START===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:19,579 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4523:ctx-42fbbdc2 ctx-64dcb855) (logid:8f764742) ===END===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:20,660 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198) (logid:3f3fe7b9) Executing AsyncJobVO {id:42198, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAALdnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAACnBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAdzcQB-AAgAAAAAAAAAOHBwcHNxAH4ACAAAAAAAAAAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAAEdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt0AAhCb290TW9kZXQAEnJPMEFCWFFBQmt4RlIwRkRXUXQACEJvb3RUeXBldAAPck8wQUJYUUFCRlZGUmtrdAAIVWVmaUZsYWd0AA5yTzBBQlhRQUExbGxjd3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90520735245649, completeMsid: null, lastUpdated: null, lastPolled: null, created: Wed Dec 08 10:03:19 HKT 2021, removed: null}
2021-12-08 10:03:20,661 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198) (logid:3f3fe7b9) Run VM work job: com.cloud.vm.VmWorkStart for VM 2934, job origin: 42197
2021-12-08 10:03:20,663 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":10,"podId":10,"clusterId":7,"hostId":56,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk","BootMode":"rO0ABXQABkxFR0FDWQ","BootType":"rO0ABXQABFVFRkk","UefiFlag":"rO0ABXQAA1llcw"},"userId":2,"accountId":2,"vmId":2934,"handlerName":"VirtualMachineManagerImpl"}
2021-12-08 10:03:20,695 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"} state transited from [Stopped] to [Starting] with event [StartRequested]. VM's original host: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}, new host: null, host before state transition: null
2021-12-08 10:03:20,695 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Successfully transitioned to start state for VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"} reservation id = 6bcca65a-e0fc-464c-9ed9-5db5a37f87c6
2021-12-08 10:03:20,702 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) advanceStart: DeploymentPlan is provided, using dcId:10, podId: 10, clusterId: 7, hostId: 56, poolId: null
2021-12-08 10:03:20,705 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Updating resource Type = user_vm count for Account = 2 Operation = increasing Amount = 1
2021-12-08 10:03:20,719 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Updating resource Type = cpu count for Account = 2 Operation = increasing Amount = 2
2021-12-08 10:03:20,728 DEBUG [c.c.r.ResourceLimitManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Updating resource Type = memory count for Account = 2 Operation = increasing Amount = 4096
2021-12-08 10:03:20,736 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Deploy avoids pods: null, clusters: null, hosts: null
2021-12-08 10:03:20,738 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) VM start attempt #1
2021-12-08 10:03:20,741 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Root volume is ready, need to place VM in volume's cluster
2021-12-08 10:03:20,741 INFO  [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Uefi params UefiFlag: Yes Boot Type: UEFI Boot Mode: LEGACY
2021-12-08 10:03:20,748 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) DeploymentPlanner allocation algorithm: null
2021-12-08 10:03:20,748 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Trying to allocate a host and storage pools from dc:10, pod:10,cluster:7, requested cpu: 3000, requested ram: (4.00 GB) 4294967296
2021-12-08 10:03:20,748 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Is ROOT volume READY (pool already allocated)?: Yes
2021-12-08 10:03:20,754 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 56
2021-12-08 10:03:20,756 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Looking for suitable pools for this host under zone: 10, pod: 10, cluster: 7
2021-12-08 10:03:20,760 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Checking suitable pools for volume (Id, Type): (3621,ROOT)
2021-12-08 10:03:20,760 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Volume has pool already allocated, checking if pool can be reused, poolId: 3
2021-12-08 10:03:20,761 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Planner need not allocate a pool for this volume since its READY
2021-12-08 10:03:20,761 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2021-12-08 10:03:20,763 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Checking if host: 56 can access any suitable storage pool for volume: ROOT
2021-12-08 10:03:20,764 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Host: 56 can access pool: 3
2021-12-08 10:03:20,766 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Found a potential host id: 56 name: compute-12.lab.example.com and associated storage pools for this VM
2021-12-08 10:03:20,768 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(10)-Pod(10)-Cluster(7)-Host(56)-Storage()]
2021-12-08 10:03:20,769 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Deployment found - Attempt #1 - P0=VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"}, P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(10)-Pod(10)-Cluster(7)-Host(56)-Storage()]
2021-12-08 10:03:20,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"} state transited from [Starting] to [Starting] with event [OperationRetry]. VM's original host: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}, new host: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}, host before state transition: null
2021-12-08 10:03:20,866 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) VM starting again on the last host it was stopped on
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Hosts's actual total CPU: 140000 and CPU after applying overprovisioning: 1680000
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) We are allocating VM, increasing the used capacity of this host:56
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Current Used CPU: 190000 , Free CPU:1487000 ,Requested CPU: 3000
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Current Used RAM: (290.25 GB) 311653564416 , Free RAM:(82.43 GB) 88509382656 ,Requested RAM: (4.00 GB) 4294967296
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Reserved CPU: 3000 , Requested CPU: 3000
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Reserved RAM: (4.00 GB) 4294967296 , Requested RAM: (4.00 GB) 4294967296
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) CPU STATS after allocation: for host: 56, old used: 190000, old reserved: 3000, actual total: 140000, total with overprovisioning: 1680000; new used:193000, reserved:0; requested cpu:3000,alloc_from_last:true
2021-12-08 10:03:20,881 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) RAM STATS after allocation: for host: 56, old used: (290.25 GB) 311653564416, old reserved: (4.00 GB) 4294967296, total: (376.68 GB) 404457914368; new used: (294.25 GB) 315948531712, reserved: (0 bytes) 0; requested mem: (4.00 GB) 4294967296,alloc_from_last:true
2021-12-08 10:03:20,884 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Host: 56 has cpu capability (cpu:56, speed:2500) to support requested CPU: 2 and requested speed: 1500
2021-12-08 10:03:20,884 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Checking if host: 56 has enough capacity for requested CPU: 3000 and requested RAM: (4.00 GB) 4294967296 , cpuOverprovisioningFactor: 12.0
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Hosts's actual total CPU: 140000 and CPU after applying overprovisioning: 1680000
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) We need to allocate to the last host again, so checking if there is enough reserved capacity
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Reserved CPU: 3000 , Requested CPU: 3000
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Reserved RAM: (4.00 GB) 4294967296 , Requested RAM: (4.00 GB) 4294967296
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Host has enough CPU and RAM available
2021-12-08 10:03:20,886 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) STATS: Can alloc CPU from host: 56, used: 190000, reserved: 3000, actual total: 140000, total with overprovisioning: 1680000; requested cpu:3000,alloc_from_last_host?:true ,considerReservedCapacity?: true
2021-12-08 10:03:20,887 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) STATS: Can alloc MEM from host: 56, used: (290.25 GB) 311653564416, reserved: (4.00 GB) 4294967296, total: (376.68 GB) 404457914368; requested mem: (4.00 GB) 4294967296, alloc_from_last_host?: true , considerReservedCapacity?: true
2021-12-08 10:03:20,898 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Network id=292 is already implemented
2021-12-08 10:03:21,138 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:21,141 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Changing active number of nics for network id=292 on 1
2021-12-08 10:03:21,244 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Asking VirtualRouter to prepare for Nic[4619-2934-6bcca65a-e0fc-464c-9ed9-5db5a37f87c6-10.1.1.178]
2021-12-08 10:03:21,263 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:21,267 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) CONFIG DHCP FOR SUBNETS RULES
2021-12-08 10:03:21,281 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:21,285 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) APPLYING VPC DHCP ENTRY RULES
2021-12-08 10:03:21,287 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Applying dhcp entry in network Ntwk[292|Guest|8]
2021-12-08 10:03:21,314 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 67-8423138678066816044: Sending  { Cmd , MgmtId: 90520735245649, via: 67(compute-18.lab.example.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:33:4c:00:0f","vmIpAddress":"10.1.1.178","vmName":"UEFI-TEST","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:33:4c:00:0f","isDefault":"true","executeInSequence":"false","remove":"false","accessDetails":{"router.name":"r-606-VM","router.guest.ip":"10.1.1.1","router.ip":"169.254.215.72","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2021-12-08 10:03:22,133 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 67-8423138678066816044: Received:  { Ans: , MgmtId: 90520735245649, via: 67(compute-18.lab.example.com), Ver: v1, Flags: 10, { GroupAnswer } }
2021-12-08 10:03:22,144 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:22,155 DEBUG [o.a.c.n.t.AdvancedNetworkTopology] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) APPLYING VPC USERDATA RULES
2021-12-08 10:03:22,156 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Applying userdata and password entry in network Ntwk[292|Guest|8]
2021-12-08 10:03:22,178 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 67-8423138678066816045: Sending  { Cmd , MgmtId: 90520735245649, via: 67(compute-18.lab.example.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"10.1.1.178","vmName":"UEFI-TEST","executeInSequence":"false","accessDetails":{"router.name":"r-606-VM","router.guest.ip":"10.1.1.1","router.ip":"169.254.215.72","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.178","vmName":"UEFI-TEST","executeInSequence":"false","accessDetails":{"router.name":"r-606-VM","router.guest.ip":"10.1.1.1","router.ip":"169.254.215.72","zone.network.type":"Advanced"},"wait":"0","bypassHostMaintenance":"false"}}] }
2021-12-08 10:03:22,618 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4523:ctx-17b08be4) (logid:0988be93) ===START===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:22,651 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4523:ctx-17b08be4 ctx-4ea3ef78) (logid:0988be93) ===END===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:23,804 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 67-8423138678066816045: Received:  { Ans: , MgmtId: 90520735245649, via: 67(compute-18.lab.example.com), Ver: v1, Flags: 10, { GroupAnswer, GroupAnswer } }
2021-12-08 10:03:23,805 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:23,810 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) No need to recreate the volume: Vol[3621|vm=2934|ROOT], since it already has a pool assigned: 3, adding disk to VM
2021-12-08 10:03:23,895 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 56-6436488292442570867: Sending  { Cmd , MgmtId: 90520735245649, via: 56(compute-12.lab.example.com), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":"2934","name":"i-2-2934-VM","state":"Starting","type":"User","cpus":"2","minSpeed":"125","maxSpeed":"1500","minRam":"(4.00 GB) 4294967296","maxRam":"(4.00 GB) 4294967296","arch":"x86_64","os":"Windows Server 2019 (64-bit)","platformEmulator":"Windows Server 2019","bootArgs":"","enableHA":"false","limitCpuUse":"false","enableDynamicallyScaleVm":"false","vncPassword":"naia7EGc8sG1kGpZgP0_8Q","params":{"cpuOvercommitRatio":"12","UEFI":"LEGACY","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"8c00e797-c713-4f4e-9a24-12c3436cf06f","bootType":"UEFI","bootMode":"LEGACY","enterHardwareSetup":"false","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"5db4c6c5-cc09-4f99-af42-c2256f76748c","name":"sg1","id":"3","poolType":"SharedMountPoint","host":"localhost","path":"/cloudstack/sg1","port":"0","url":"SharedMountPoint://localhost/cloudstack/sg1/?ROLE=Primary&STOREUUID=5db4c6c5-cc09-4f99-af42-c2256f76748c","isManaged":"false"}},"name":"ROOT-2934","size":"(50.00 GB) 53687091200","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeId":"3621","vmName":"i-2-2934-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"3","id":"3621","deviceId":"0","bytesReadRate":"(0 bytes) 0","bytesWriteRate":"(0 bytes) 0","iopsReadRate":"(0 bytes) 0","iopsWriteRate":"(0 bytes) 0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"}},"diskSeq":"0","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","type":"ROOT","_details":{"storageHost":"localhost","managed":"false","storagePort":"0","storage.pool.disk.wait":"60","volumeSize":"(50.00 GB) 53687091200"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":"0","format":"ISO","accountId":"0","hvm":"false","bootable":"false","directDownload":"false","deployAsIs":"false"}},"diskSeq":"3","type":"ISO"}],"nics":[{"deviceId":"0","networkRateMbps":"1000","defaultNic":"true","pxeDisable":"false","nicUuid":"9dd86ec5-013d-413d-9e2a-279da6ed8603","details":{"MacLearning":"false","MacAddressChanges":"true","PromiscuousMode":"false","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"12fd40ee-ea95-4d32-bafe-1b005b62e9fa","ip":"10.1.1.178","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:33:4c:00:0f","dns1":"172.16.2.1","dns2":"","broadcastType":"Vxlan","type":"Guest","broadcastUri":"vxlan://3138","isolationUri":"vxlan://3138","isSecurityGroupEnabled":"false","name":"bond0.1000"}],"vcpuMaxLimit":"2","configDriveLocation":"SECONDARY","guestOsDetails":{},"extraConfig":{}},"hostIp":"172.16.0.32","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}] }
2021-12-08 10:03:25,604 DEBUG [c.c.a.t.Request] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Seq 56-6436488292442570867: Received:  { Ans: , MgmtId: 90520735245649, via: 56(compute-12.lab.example.com), Ver: v1, Flags: 10, { StartAnswer } }
2021-12-08 10:03:25,678 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:25,682 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Service SecurityGroup is not supported in the network id=292
2021-12-08 10:03:25,685 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"} state transited from [Starting] to [Running] with event [OperationSucceeded]. VM's original host: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}, new host: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}, host before state transition: Host {"id": "56", "name": "compute-12.lab.example.com", "uuid": "c1fed481-7898-45bb-93ca-347784610714", "type"="Routing"}
2021-12-08 10:03:25,693 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Start completed for VM VM instance {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type="User"}
2021-12-08 10:03:25,694 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Done executing VM work job: com.cloud.vm.VmWorkStart{"dcId":10,"podId":10,"clusterId":7,"hostId":56,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk","BootMode":"rO0ABXQABkxFR0FDWQ","BootType":"rO0ABXQABFVFRkk","UefiFlag":"rO0ABXQAA1llcw"},"userId":2,"accountId":2,"vmId":2934,"handlerName":"VirtualMachineManagerImpl"}
2021-12-08 10:03:25,696 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Complete async job-42198, jobStatus: SUCCEEDED, resultCode: 0, result: null
2021-12-08 10:03:25,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Publish async job-42198 complete on message bus
2021-12-08 10:03:25,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Wake up jobs related to job-42198
2021-12-08 10:03:25,697 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Update db status for job-42198
2021-12-08 10:03:25,699 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198 ctx-25f3fe43) (logid:3f3fe7b9) Wake up jobs joined with job-42198 and disjoin all subjobs created from job- 42198
2021-12-08 10:03:25,709 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198) (logid:3f3fe7b9) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 2934, job origin: 42197
2021-12-08 10:03:25,709 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198) (logid:3f3fe7b9) Done executing com.cloud.vm.VmWorkStart for job-42198
2021-12-08 10:03:25,712 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-84:ctx-9a1312fe job-42197/job-42198) (logid:3f3fe7b9) Remove job-42198 from job monitoring
2021-12-08 10:03:25,720 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4521:ctx-fd6096f0) (logid:c8f05370) ===START===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:25,750 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4521:ctx-fd6096f0 ctx-31763eda) (logid:c8f05370) ===END===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:25,756 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Complete async job-42197, jobStatus: SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"8c00e797-c713-4f4e-9a24-12c3436cf06f","name":"UEFI-TEST","displayname":"UEFI-TEST","account":"admin","userid":"918f6bbb-0005-11eb-92dc-52540044e551","username":"admin","domainid":"50e7a615-0005-11eb-92dc-52540044e551","domain":"ROOT","created":"2021-12-07T19:39:57+0800","lastupdated":"2021-12-08T10:03:25+0800","state":"Running","haenable":"false","zoneid":"5e43ac5b-d657-49f2-98e1-7304476d28ed","zonename":"apac-1a","hostid":"c1fed481-7898-45bb-93ca-347784610714","hostname":"compute-12.lab.example.com","templateid":"ad428ab1-1a65-4a25-85f1-01422f941a8f","templatename":"17763.737.190906-2324.rs5_release_svc_refresh_SERVER_EVAL_x64FRE_en-us_1","templatedisplaytext":"Windows 2019","passwordenabled":"false","serviceofferingid":"2cb14da7-3211-49dd-8cb4-a53947fb31f5","serviceofferingname":"w2","diskofferingid":"b84f2088-3c70-4a5e-8948-81f564ad8277","diskofferingname":"Medium","cpunumber":"2","cpuspeed":"1500","memory":"4096","cpuused":"0.15%","networkkbsread":"(0 bytes) 0","networkkbswrite":"(0 bytes) 0","diskkbsread":"(4 bytes) 4","diskkbswrite":"(0 bytes) 0","memorykbs":"(4.00 MB) 4194304","memoryintfreekbs":"(0 bytes) 0","memorytargetkbs":"(4.00 MB) 4194304","diskioread":"(8 bytes) 8","diskiowrite":"(0 bytes) 0","guestosid":"7af8f9eb-0005-11eb-92dc-52540044e551","rootdeviceid":"0","rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"9dd86ec5-013d-413d-9e2a-279da6ed8603","networkid":"12fd40ee-ea95-4d32-bafe-1b005b62e9fa","networkname":"test","netmask":"255.255.255.0","gateway":"10.1.1.1","ipaddress":"10.1.1.178","isolationuri":"vxlan://3138","broadcasturi":"vxlan://3138","traffictype":"Guest","type":"Isolated","isdefault":"true","macaddress":"02:00:33:4c:00:0f","secondaryip":[],"extradhcpoption":[],"deviceid":"0"}],"hypervisor":"KVM","instancename":"i-2-2934-VM","details":{"UEFI":"LEGACY","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"12"},"affinitygroup":[],"displayvm":"true","isdynamicallyscalable":"false","ostypeid":"7af8f9eb-0005-11eb-92dc-52540044e551","osdisplayname":"Windows Server 2019 (64-bit)","bootmode":"legacy","boottype":"Uefi","pooltype":"SharedMountPoint","receivedbytes":"0","sentbytes":"0","tags":[],"hasannotations":"false","jobid":"3f3fe7b9-e6be-4358-8458-21d591dbfc55","jobstatus":"0"}
2021-12-08 10:03:25,758 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Publish async job-42197 complete on message bus
2021-12-08 10:03:25,758 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Wake up jobs related to job-42197
2021-12-08 10:03:25,758 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Update db status for job-42197
2021-12-08 10:03:25,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197 ctx-81408b67) (logid:3f3fe7b9) Wake up jobs joined with job-42197 and disjoin all subjobs created from job- 42197
2021-12-08 10:03:25,767 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-63:ctx-c879ee45 job-42197) (logid:3f3fe7b9) Done executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-42197
2021-12-08 10:03:25,768 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-63:ctx-c879ee45 job-42197) (logid:3f3fe7b9) Remove job-42197 from job monitoring
2021-12-08 10:03:28,867 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4521:ctx-5d10b6ec) (logid:9124d0cd) ===START===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json
2021-12-08 10:03:28,912 DEBUG [c.c.a.ApiServlet] (qtp2129144075-4521:ctx-5d10b6ec ctx-181f14ff) (logid:9124d0cd) ===END===  172.16.2.4 -- GET  jobId=3f3fe7b9-e6be-4358-8458-21d591dbfc55&command=queryAsyncJobResult&response=json

Agent debug log


2021-12-08 10:03:22,647 DEBUG [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:1906cf03) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2021-12-08 10:03:22,647 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:1906cf03) Trying to fetch storage pool 5db4c6c5-cc09-4f99-af42-c2256f76748c from libvirt
2021-12-08 10:03:22,647 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-2:null) (logid:1906cf03) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:22,650 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:1906cf03) Asking libvirt to refresh storage pool 5db4c6c5-cc09-4f99-af42-c2256f76748c
2021-12-08 10:03:23,902 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Request:Seq 56-6436488292442570867:  { Cmd , MgmtId: 90520735245649, via: 56, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":"2934","name":"i-2-2934-VM","state":"Starting","type":"User","cpus":"2","minSpeed":"125","maxSpeed":"1500","minRam":"(4.00 GB) 4294967296","maxRam":"(4.00 GB) 4294967296","arch":"x86_64","os":"Windows Server 2019 (64-bit)","platformEmulator":"Windows Server 2019","bootArgs":"","enableHA":"false","limitCpuUse":"false","enableDynamicallyScaleVm":"false","vncPassword":"naia7EGc8sG1kGpZgP0_8Q","params":{"cpuOvercommitRatio":"12","UEFI":"LEGACY","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"8c00e797-c713-4f4e-9a24-12c3436cf06f","bootType":"UEFI","bootMode":"LEGACY","enterHardwareSetup":"false","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"5db4c6c5-cc09-4f99-af42-c2256f76748c","name":"sg1","id":"3","poolType":"SharedMountPoint","host":"localhost","path":"/cloudstack/sg1","port":"0","url":"SharedMountPoint://localhost/cloudstack/sg1/?ROLE=Primary&STOREUUID=5db4c6c5-cc09-4f99-af42-c2256f76748c","isManaged":"false"}},"name":"ROOT-2934","size":"(50.00 GB) 53687091200","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeId":"3621","vmName":"i-2-2934-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"3","id":"3621","deviceId":"0","bytesReadRate":"(0 bytes) 0","bytesWriteRate":"(0 bytes) 0","iopsReadRate":"(0 bytes) 0","iopsWriteRate":"(0 bytes) 0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"}},"diskSeq":"0","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","type":"ROOT","_details":{"storageHost":"localhost","managed":"false","storagePort":"0","storage.pool.disk.wait":"60","volumeSize":"(50.00 GB) 53687091200"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":"0","format":"ISO","accountId":"0","hvm":"false","bootable":"false","directDownload":"false","deployAsIs":"false"}},"diskSeq":"3","type":"ISO"}],"nics":[{"deviceId":"0","networkRateMbps":"1000","defaultNic":"true","pxeDisable":"false","nicUuid":"9dd86ec5-013d-413d-9e2a-279da6ed8603","details":{"MacLearning":"false","MacAddressChanges":"true","PromiscuousMode":"false","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"12fd40ee-ea95-4d32-bafe-1b005b62e9fa","ip":"10.1.1.178","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:33:4c:00:0f","dns1":"172.16.2.1","dns2":"","broadcastType":"Vxlan","type":"Guest","broadcastUri":"vxlan://3138","isolationUri":"vxlan://3138","isSecurityGroupEnabled":"false","name":"bond0.1000"}],"vcpuMaxLimit":"2","configDriveLocation":"SECONDARY","guestOsDetails":{},"extraConfig":{}},"hostIp":"172.16.0.32","executeInSequence":"false","wait":"0","bypassHostMaintenance":"false"}}] }
2021-12-08 10:03:23,902 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Processing command: com.cloud.agent.api.StartCommand
2021-12-08 10:03:23,902 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Creating VM from specifications [VM {id: "2934", name: "i-2-2934-VM", uuid: "8c00e797-c713-4f4e-9a24-12c3436cf06f", type: "User"}]
2021-12-08 10:03:23,902 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Enabled UEFI for VM UUID [8c00e797-c713-4f4e-9a24-12c3436cf06f].
2021-12-08 10:03:23,903 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Configuring VM with UUID [8c00e797-c713-4f4e-9a24-12c3436cf06f].
2021-12-08 10:03:23,903 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:23,904 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Trying to fetch storage pool 5db4c6c5-cc09-4f99-af42-c2256f76748c from libvirt
2021-12-08 10:03:23,904 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:24,115 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-2:null) (logid:1906cf03) Succesfully refreshed pool 5db4c6c5-cc09-4f99-af42-c2256f76748c Capacity: (143.9470 TB) 158271440683008 Used: (27.6577 TB) 30409932931072 Available: (116.2894 TB) 127861507751936
2021-12-08 10:03:24,117 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Succesfully refreshed pool 5db4c6c5-cc09-4f99-af42-c2256f76748c Capacity: (143.9470 TB) 158271440683008 Used: (27.6577 TB) 30409932931072 Available: (116.2894 TB) 127861507751936
2021-12-08 10:03:24,120 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:24,121 DEBUG [utils.script.Script] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Executing: qemu-img info -U /cloudstack/sg1/2d837256-b367-4c00-9ce5-f91d963e8ef5
2021-12-08 10:03:24,122 DEBUG [utils.script.Script] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Executing while with timeout : 3600000
2021-12-08 10:03:24,158 DEBUG [utils.script.Script] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Execution is successful.
2021-12-08 10:03:24,159 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Trying to fetch storage pool 5db4c6c5-cc09-4f99-af42-c2256f76748c from libvirt
2021-12-08 10:03:24,159 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:24,163 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Succesfully refreshed pool 5db4c6c5-cc09-4f99-af42-c2256f76748c Capacity: (143.9470 TB) 158271440683008 Used: (27.6577 TB) 30409932931072 Available: (116.2894 TB) 127861507751936
2021-12-08 10:03:24,163 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) nic=[Nic:Guest-10.1.1.178-vxlan://3138]
2021-12-08 10:03:24,163 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) creating a vNet dev and bridge for guest traffic per traffic label bond0.1000
2021-12-08 10:03:24,163 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Executing: /usr/share/cloudstack-common/scripts/vm/network/vnet/modifyvxlan.sh -v 3138 -p bond0.1000 -b brvx-3138 -o add
2021-12-08 10:03:24,164 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Executing while with timeout : 1800000
2021-12-08 10:03:24,190 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Execution is successful.
2021-12-08 10:03:24,190 DEBUG [kvm.resource.BridgeVifDriver] (agentRequest-Handler-1:null) (logid:3f3fe7b9) multicast 239.0.12.66 for VNI 3138 on bond0.1000

2021-12-08 10:03:24,190 DEBUG [resource.wrapper.LibvirtStartCommandWrapper] (agentRequest-Handler-1:null) (logid:3f3fe7b9) starting i-2-2934-VM: <domain type='kvm'>
<name>i-2-2934-VM</name>
<uuid>8c00e797-c713-4f4e-9a24-12c3436cf06f</uuid>
<description>Windows Server 2019 (64-bit)</description>
<cpu mode='host-passthrough'><feature policy='require' name='vmx'/></cpu><sysinfo type='smbios'>
<system>
<entry name='manufacturer'>Apache Software Foundation</entry>
<entry name='product'>CloudStack KVM Hypervisor</entry>
<entry name='uuid'>8c00e797-c713-4f4e-9a24-12c3436cf06f</entry>
</system>
</sysinfo>
<os>
<type  arch='x86_64' machine='q35'>hvm</type>
<nvram template='/usr/share/OVMF/OVMF_VARS.fd'>/var/lib/libvirt/qemu/nvram/8c00e797-c713-4f4e-9a24-12c3436cf06f.fd</nvram><boot dev='cdrom'/>
<boot dev='hd'/>
<smbios mode='sysinfo'/>
</os>
<on_reboot>restart</on_reboot>
<on_poweroff>destroy</on_poweroff>
<on_crash>destroy</on_crash>
<memory>4194304</memory>
<currentMemory>4194304</currentMemory>
<devices>
<memballoon model='virtio'/>
</devices>
<vcpu current="2">2</vcpu>
<features>
<pae/>
<apic/>
<acpi/>
</features>
<cputune>
<shares>250</shares>
</cputune>
<clock offset='localtime'>
<timer name='hypervclock' present='yes' /></clock>
<devices>
<emulator>/usr/libexec/qemu-kvm</emulator>
<watchdog model='i6300esb' action='none'/>
<console type='pty'>
<target port='0'/>
</console>
<disk  device='disk' type='file'>
<driver name='qemu' type='qcow2' cache='none' />
<source file='/cloudstack/sg1/2d837256-b367-4c00-9ce5-f91d963e8ef5'/>
<target dev='sda' bus='sata'/>
<serial>2d837256b3674c009ce5</serial></disk>
<disk  device='cdrom' type='file'>
<driver name='qemu' type='raw' />
<source file=''/>
<target dev='sdd' bus='sata'/>
</disk>
<serial type='pty'>
<target port='0'/>
</serial>
<graphics type='vnc' autoport='yes' listen='172.16.0.32' passwd='naia7EGc8sG1kGpZgP0_8Q'/>
<channel type='unix'>
<source mode='bind' path='/var/lib/libvirt/qemu/i-2-2934-VM.org.qemu.guest_agent.0'/>
<address type='virtio-serial'/>
<target type='virtio' name='org.qemu.guest_agent.0'/>
</channel>
<rng model='virtio'>
<rate period='1000' bytes='2048' />
<backend model='random'>/dev/urandom</backend></rng>
<input type='tablet' bus='usb'/>
<interface type='bridge'>
<source bridge='brvx-3138'/>
<mac address='02:00:33:4c:00:0f'/>
<model type='e1000'/>
<bandwidth>
<inbound average='128000' peak='128000'/>
<outbound average='128000' peak='128000'/>
</bandwidth>
<link state='up'/>
</interface>
</devices>
</domain>

2021-12-08 10:03:24,191 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-xml-transformer.groovy' is not available. Transformations will not be applied.
2021-12-08 10:03:24,191 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Groovy scripting engine is not initialized. Data transformation skipped.
2021-12-08 10:03:24,853 DEBUG [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:1906cf03) Processing command: com.cloud.agent.api.GetStorageStatsCommand
2021-12-08 10:03:24,854 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:1906cf03) Trying to fetch storage pool 0d481986-52c0-4493-909c-6b5955c66954 from libvirt
2021-12-08 10:03:24,854 DEBUG [kvm.resource.LibvirtConnection] (agentRequest-Handler-3:null) (logid:1906cf03) Looking for libvirtd connection at: qemu:///system
2021-12-08 10:03:24,856 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:1906cf03) Asking libvirt to refresh storage pool 0d481986-52c0-4493-909c-6b5955c66954
2021-12-08 10:03:24,858 DEBUG [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-3:null) (logid:1906cf03) Succesfully refreshed pool 0d481986-52c0-4493-909c-6b5955c66954 Capacity: (1.8619 TB) 2047145672704 Used: (33.53 MB) 35160064 Available: (1.8618 TB) 2047110512640
2021-12-08 10:03:25,590 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Groovy script '/etc/cloudstack/agent/hooks/libvirt-vm-state-change.groovy' is not available. Transformations will not be applied.
2021-12-08 10:03:25,590 WARN  [kvm.resource.LibvirtKvmAgentHook] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Groovy scripting engine is not initialized. Data transformation skipped.
2021-12-08 10:03:25,590 DEBUG [kvm.resource.LibvirtComputingResource] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Checking default network rules for vm i-2-2934-VM
2021-12-08 10:03:25,597 DEBUG [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:3f3fe7b9) Seq 56-6436488292442570867:  { Ans: , MgmtId: 90520735245649, via: 56, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":"2934","name":"i-2-2934-VM","state":"Starting","type":"User","cpus":"2","minSpeed":"125","maxSpeed":"1500","minRam":"(4.00 GB) 4294967296","maxRam":"(4.00 GB) 4294967296","arch":"x86_64","os":"Windows Server 2019 (64-bit)","platformEmulator":"Windows Server 2019","bootArgs":"","enableHA":"false","limitCpuUse":"false","enableDynamicallyScaleVm":"false","vncPassword":"naia7EGc8sG1kGpZgP0_8Q","vncAddr":"172.16.0.32","params":{"cpuOvercommitRatio":"12","UEFI":"LEGACY","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false"},"uuid":"8c00e797-c713-4f4e-9a24-12c3436cf06f","bootType":"UEFI","bootMode":"LEGACY","enterHardwareSetup":"false","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"5db4c6c5-cc09-4f99-af42-c2256f76748c","name":"sg1","id":"3","poolType":"SharedMountPoint","host":"localhost","path":"/cloudstack/sg1","port":"0","url":"SharedMountPoint://localhost/cloudstack/sg1/?ROLE=Primary&STOREUUID=5db4c6c5-cc09-4f99-af42-c2256f76748c","isManaged":"false"}},"name":"ROOT-2934","size":"(50.00 GB) 53687091200","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","volumeId":"3621","vmName":"i-2-2934-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","poolId":"3","id":"3621","deviceId":"0","bytesReadRate":"(0 bytes) 0","bytesWriteRate":"(0 bytes) 0","iopsReadRate":"(0 bytes) 0","iopsWriteRate":"(0 bytes) 0","cacheMode":"NONE","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"}},"diskSeq":"0","path":"2d837256-b367-4c00-9ce5-f91d963e8ef5","type":"ROOT","_details":{"storageHost":"localhost","managed":"false","storagePort":"0","storage.pool.disk.wait":"60","volumeSize":"(50.00 GB) 53687091200"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":"0","format":"ISO","accountId":"0","hvm":"false","bootable":"false","directDownload":"false","deployAsIs":"false"}},"diskSeq":"3","type":"ISO"}],"nics":[{"deviceId":"0","networkRateMbps":"1000","defaultNic":"true","pxeDisable":"false","nicUuid":"9dd86ec5-013d-413d-9e2a-279da6ed8603","details":{"MacLearning":"false","MacAddressChanges":"true","PromiscuousMode":"false","ForgedTransmits":"true"},"dpdkEnabled":"false","uuid":"12fd40ee-ea95-4d32-bafe-1b005b62e9fa","ip":"10.1.1.178","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:33:4c:00:0f","dns1":"172.16.2.1","dns2":"","broadcastType":"Vxlan","type":"Guest","broadcastUri":"vxlan://3138","isolationUri":"vxlan://3138","isSecurityGroupEnabled":"false","name":"bond0.1000"}],"vcpuMaxLimit":"2","configDriveLocation":"SECONDARY","guestOsDetails":{},"extraConfig":{}},"result":"true","wait":"0","bypassHostMaintenance":"false"}}] }
levindecaro commented 2 years ago

The directives should look like below in order to start VM in UEFI legacy mode.

  <os>
    <type arch='x86_64' machine='pc-q35-rhel7.6.0'>hvm</type>
    <loader readonly='yes' secure='no' type='pflash'>/usr/share/OVMF/OVMF_CODE.secboot.fd</loader>
    <nvram template='/usr/share/OVMF/OVMF_VARS.fd'>/var/lib/libvirt/qemu/nvram/8c00e797-c713-4f4e-9a24-12c3436cf06f.fd</nvram>
    <boot dev='cdrom'/>
    <boot dev='hd'/>
  </os>
leolleeooleo commented 2 years ago

I have this issues too. After I upgrade from 4.15.2

OS / ENVIRONMENT Rocky Linux release 8.5 (Green Obsidian)

leolleeooleo commented 2 years ago

I think it should be fixed in #5692.

DaanHoogland commented 2 years ago

I think it should be fixed in #5692.

that pr would address the <loader readonly='yes' secure='no' type='pflash'>/usr/share/OVMF/OVMF_CODE.secboot.fd</loader>, part, @leolleeooleo . I don't think it adds the <nvram template='/usr/share/OVMF/OVMF_VARS.fd'>/var/lib/libvirt/qemu/nvram/8c00e797-c713-4f4e-9a24-12c3436cf06f.fd</nvram>, which would be needed as well.

Also i'm not sure it will leave the <smbios mode='sysinfo'/> out and whether that is required/fatal. Can you guys test that PR in and report back? (cc @levindecaro )

leolleeooleo commented 2 years ago

In the agent debug log nvram is fine. I think it just miss something (loader) so libvirt remove it. The code vnram was missing '\n' at the end.

leolleeooleo commented 2 years ago

I rebase #5692 to tag 4.16.0.0, and replace cloud-plugin-hypervisor-kvm-4.16.0.0.jar UEFI works fine.

My steps:

$ git checkout -b test a85a00bed97bf222acbc28eda893f4ddc57b1f09

$ git rebase -i 4.16.0.0
:1,10s/pick/drop/g
drop 93c3c3b9ac Updating pom.xml version numbers for release 4.16.1.0-SNAPSHOT
drop 462e0511f4 Fix version and add schema upgrade path
drop bdab51424a New upgrade schema path and workaround for system VM template auto registration
drop 4568a68d83 CsDhcp.py: fix runtests.sh error (#5671)
drop 0684aff529 ui: fix incorrect auto-select (#5693)
drop a8e7315e53 UI : Fix SSL certificate submit button not working (#5682)
drop e93d67444d ui-primary-storage: hide provider if Linstor protocol (#5672)
drop c95f8e263a server: set network rate for additional public IPs (#5670)
drop dd458feeb8 IPv6: fix deploy vm issue in ipv6-only networks without VR (#5648)
drop babf94f801 UI: Autoscroll to Error Field (#5200)
pick a85a00bed9 kvm: Fixes UEFI XML Definition Error (#5692)

# Rebase 44c08b5acc..a85a00bed9 onto c95f8e263a (11 commands)

:wq

$ git log
commit 616791c0f0e0e1deeb2457afe4fbecccf552e8b2 (HEAD -> test)
Author: DH Park <pdh1974@gmail.com>
Date:   Tue Nov 23 20:14:32 2021 +0900

    kvm: Fixes UEFI XML Definition Error (#5692)

    UEFI bootMode 추가

commit 44c08b5acc598972b4f0af576ffdea4e2447cb41 (tag: 4.16.0.0)
Author: nicolas <nicovazquez90@gmail.com>
Date:   Thu Nov 4 14:14:57 2021 -0300

    Updating pom.xml version numbers for release 4.16.0.0

    Signed-off-by: nicolas <nicovazquez90@gmail.com>

$ git diff 4.16.0.0
diff --git a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/LibvirtComputingResource.java b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/LibvirtComputingResource.java
index 46763a151f..9684b7e224 100644
--- a/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/LibvirtComputingResource.java
+++ b/plugins/hypervisors/kvm/src/main/java/com/cloud/hypervisor/kvm/resource/LibvirtComputingResource.java
@@ -2357,6 +2357,8 @@ public class LibvirtComputingResource extends ServerResourceBase implements Serv
                 s_logger.debug(String.format("Enabled Secure Boot for VM UUID [%s].", uuid));
                 isSecureBoot = true;
             }
+
+            bootMode = customParams.get(GuestDef.BootType.UEFI.toString());
         }

         Map<String, String> extraConfig = vmTO.getExtraConfig();

$ mvn install
$ scp plugins/hypervisors/kvm/target/cloud-plugin-hypervisor-kvm-4.16.0.0.jar leo@kvm-agent:

$ ssh leo@kvm-agent
$ cp /usr/share/cloudstack-agent/lib/cloud-plugin-hypervisor-kvm-4.16.0.0.jar ~/cloud-plugin-hypervisor-kvm-4.16.0.0.jar.origin
$ sudo systemctl stop cloudstack-agent.service
$ sudo cp ~/cloud-plugin-hypervisor-kvm-4.16.0.0.jar /usr/share/cloudstack-agent/lib/cloud-plugin-hypervisor-kvm-4.16.0.0.jar
$ sudo systemctl start cloudstack-agent.service
levindecaro commented 2 years ago

@DaanHoogland

Tested #5692 was fixed for this case. Thank you @leolleeooleo