Uploaded image for project: 'CloudStack'
  1. CloudStack
  2. CLOUDSTACK-10412

starting or moving VMs to new KVM Host fails with qemu error "Failed to lock byte 100" - Cloudstack 4.13.0

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • None
    • None
    • KVM
    • Security Level: Public (Anyone can view this level - this is the default.)
    • None

    Description

      In an "Advanced zone" with 1 VPC and redundant VRs (KVM Hypervisor) I created a series of VMs without problems.
      Environment:
      2 management server: Centos-release-7-7.1908.0.el7 + Cloudstack 4.13.0
      2 KVM Host: Centos-release-7-7.1908.0.el7 + Cloudstack 4.13.0 + qemu-kvm-ev-2.12.0-33.1.el7 + libvirt-4.5.0-23.el7_7
      Primary Storage: NFS mount from gluster cluster exported with nfs-ganesha / nfs-ganesha-gluster
      Secondary Storage: NFS mount from gluster cluster exported with nfs-ganesha / nfs-ganesha-gluster

      After reaching the capacity limit of the 2 KVM Host (configured without overprovisioning):

      • I changed the global variable "cpu.overprovisioning.factor" to 3.0 and
      • I added 2 new KVM hosts (Centos-release-7-7.1908.0.el7 + Cloudstack 4.13.0 + qemu-kvm-ev-2.12.0-33.1.el7 + libvirt-4.5.0-23.el7_7)

      I turned off a VM that was previously present on a KVM host.
      I tried to turn the VM back on on a new KVM host and get the following:

      *** MANAGEMENT LOG ***
      2019-10-18 15:31:52,425 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-68:ctx-5733fe82 job-1706 ctx-04163f37) (logid:bf16e30c) Complete async job-1706, jobStatus:
      {{ SUCCEEDED, resultCode: 0, result: org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"574b7ce7-7b71-47ee-900a-6b16540d97b1","name":"fe-newsletter","disp}}
      layname":"fe-newsletter","account":"alvolante","userid":"d3206703-cf6b-42df-a529-85956de340af","username":"alvolante","domainid":"baa1ec1c-f80c-4347-b52a-dee9053cb9e1","doma
      in":"ALVOLANTE","created":"2019-10-10T14:36:36+0200","state":"Stopped","haenable":true,"zoneid":"64e1c0d5-cd47-439f-a9a9-95ccbd02f6b0","zonename":"zone1","templateid":"2d213
      585-5930-4916-814f-f911b4516333","templatename":"CentOS-7.7 (30GB disk minimum)","templatedisplaytext":"CentOS-7.7 minimal + tools","passwordenabled":true,"serviceofferingid
      ":"134b3a95-7a8e-49b1-95f4-55077c9582ae","serviceofferingname":"Advanced Compute","cpunumber":2,"cpuspeed":2400,"memory":4096,"cpuused":"0.06%","networkkbsread":79495,"netwo
      rkkbswrite":24,"diskkbsread":4,"diskkbswrite":1820,"memorykbs":4194304,"memoryintfreekbs":643532,"memorytargetkbs":4194304,"diskioread":1,"diskiowrite":249,"guestosid":"770b
      1691-e42b-11e9-958a-441ea1609f9e","rootdeviceid":0,"rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"054ffac0-0fef-465d-b505-7da773a64284","networkid":"4e5fc47c-6fdd-
      4422-8f61-de8f8991bb68","networkname":"SUBNET-ALVOLANTE","netmask":"255.255.252.0","gateway":"10.0.8.1","ipaddress":"10.0.8.189","traffictype":"Guest","type":"Isolated","isd
      efault":true,"macaddress":"02:00:5c:3e:00:22","secondaryip":[],"extradhcpoption":[]}],"hypervisor":"KVM","publicipid":"9665e766-daec-4cf9-9382-936b40271bf5","publicip":"45.1
      45.207.249","instancename":"i-11-47-VM","details":{"keyboard":"us","memoryOvercommitRatio":"1.0","Message.ReservedCapacityFreed.Flag":"false","cpuOvercommitRatio":"3.0"},"af
      finitygroup":[],"displayvm":true,"isdynamicallyscalable":true,"ostypeid":"770b1691-e42b-11e9-958a-441ea1609f9e","tags":[],"jobid":"bf16e30c-ade0-4a99-a83a-3017c9f36f30","job
      status":0}

      The VM never came up and:

       

      *** QEMU LOG ***
      {{[root@compute-04 qemu]# cat i-11-47-VM.log }}
      2019-10-18 13:31:40.017+0000: starting up libvirt version: 4.5.0, package: 23.el7_7.1 (CentOS BuildSystem <http://bugs.centos.org>, 2019-09-13-18:01:52, x86-02.bsys.centos.org), qemu version: 2.12.0qemu-kvm-ev-2.12.0-33.1.el7, kernel: 3.10.0-1062.1.2.el7.x86_64, hostname: compute-04.**************
      {{LC_ALL=C }}
      {{PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin }}
      {{QEMU_AUDIO_DRV=none }}
      {{/usr/libexec/qemu-kvm }}
      {{-name guest=i-11-47-VM,debug-threads=on }}
      {{-S }}
      {{-object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-i-11-47-VM/master-key.aes }}
      {{-machine pc-i440fx-rhel7.6.0,accel=kvm,usb=off,dump-guest-core=off }}
      {{-cpu Westmere-IBRS,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,stibp=on,ssbd=on,pdpe1gb=on,rdtscp=on }}
      {{-m 4096 }}
      {{-realtime mlock=off }}
      {{-smp 2,sockets=2,cores=1,threads=1 }}
      {{-uuid 574b7ce7-7b71-47ee-900a-6b16540d97b1 }}
      {{-smbios 'type=1,manufacturer=Apache Software Foundation,product=CloudStack KVM Hypervisor,uuid=574b7ce7-7b71-47ee-900a-6b16540d97b1' }}
      {{-no-user-config }}
      {{-nodefaults }}
      {{-chardev socket,id=charmonitor,fd=28,server,nowait }}
      {{-mon chardev=charmonitor,id=monitor,mode=control }}
      {{-rtc base=utc }}
      {{-no-shutdown }}
      {{-boot strict=on }}
      {{-device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 }}
      {{-device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x4 }}
      {{-drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/65604401-09ff-41a1-9dc9-bc0951a53aea,format=qcow2,if=none,id=drive-virtio-disk0,serial=6560440109ff41a19dc9,cache=none }}
      {{-device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x5,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2,write-cache=on }}
      {{-drive if=none,id=drive-ide0-1-0,readonly=on }}
      {{-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 }}
      {{-netdev tap,fd=30,id=hostnet0,vhost=on,vhostfd=31 }}
      {{-device virtio-net-pci,netdev=hostnet0,id=net0,mac=02:00:5c:3e:00:22,bus=pci.0,addr=0x3 }}
      {{-chardev pty,id=charserial0 }}
      {{-device isa-serial,chardev=charserial0,id=serial0 }}
      {{-chardev socket,id=charchannel0,fd=32,server,nowait }}
      {{-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 }}
      {{-device usb-tablet,id=input0,bus=usb.0,port=1 }}
      {{-vnc 192.168.145.23:0,password }}
      {{-device cirrus-vga,id=video0,bus=pci.0,addr=0x2 }}
      {{-device i6300esb,id=watchdog0,bus=pci.0,addr=0x6 }}
      {{-watchdog-action none }}
      {{-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny }}
      -msg timestamp=on
      2019-10-18 13:31:40.018+0000: Domain id=1 is tainted: high-privileges
      2019-10-18T13:31:40.151261Z qemu-kvm: -chardev pty,id=charserial0: char device redirected to /dev/pts/2 (label charserial0)
      2019-10-18T13:31:40.151471Z qemu-kvm: -drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/65604401-09ff-41a1-9dc9-bc0951a53aea,format=qcow2,if=none,id=drive-virtio-disk0,serial=6560440109ff41a19dc9,cache=none: 'serial' is deprecated, please use the corresponding option of '-device' instead
      2019-10-18T13:31:43.173865Z qemu-kvm: -drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/65604401-09ff-41a1-9dc9-bc0951a53aea,format=qcow2,if=none,id=drive-virtio-disk0,serial=6560440109ff41a19dc9,cache=none: Failed to lock byte 100
      2019-10-18 13:31:43.189+0000: shutting down, reason=failed

      Whatever action I do on the machines now gives me the error "Failed to lock byte 100" related to qemu.

      I tried to "migrate" one of the 2 VR - same error:

       

      *** MANAGEMENT LOG ***
      {{2019-10-18 15:37:37,772 DEBUG [c.c.s.ManagementServerImpl] (qtp504527234-2157:ctx-ff3278f6 ctx-4e4c6837) (logid:7339eb42) Searching for all hosts in cluster 1 for migrating }}
      VM VM[DomainRouter|r-31-VM]
      ...
      2019-10-18 15:38:07,052 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-69:ctx-0ace849d job-1710) (logid:ca86e0f7) Unexpected exception while executing org.apache.cloudstack.api.command.admin.systemvm.MigrateSystemVMCmd
      com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: internal error: unable to execute QEMU command 'cont': Failed to lock byte 100
      {{ at com.cloud.vm.VirtualMachineManagerImpl.migrate(VirtualMachineManagerImpl.java:2373)}}
      {{ at com.cloud.vm.VirtualMachineManagerImpl.orchestrateMigrate(VirtualMachineManagerImpl.java:2261)}}
      {{ at com.cloud.vm.VirtualMachineManagerImpl.orchestrateMigrate(VirtualMachineManagerImpl.java:5138)}}
      {{ at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)}}
      {{ at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)}}
      {{ at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)}}
      {{ at java.lang.reflect.Method.invoke(Method.java:498)}}
      {{ at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)}}
      {{ at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5270)}}
      {{ at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)}}
      {{ at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)}}
      {{ at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)}}
      {{ at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)}}
      {{ at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)}}
      {{ at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)}}
      {{ at java.util.concurrent.FutureTask.run(FutureTask.java:266)}}
      {{ at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)}}
      {{ at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)}}
      {{ at java.lang.Thread.run(Thread.java:748)}}
      2019-10-18 15:38:07,053 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-69:ctx-0ace849d job-1710) (logid:ca86e0f7) Complete async job-1710, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"org.libvirt.LibvirtException: internal error: unable to execute QEMU command \u0027cont\u0027: Failed to lock byte 100"}

      *** QEMU LOG ***
      {{[root@compute-04 qemu]# cat r-31-VM.log }}
      2019-10-18 13:37:47.851+0000: starting up libvirt version: 4.5.0, package: 23.el7_7.1 (CentOS BuildSystem <http://bugs.centos.org>, 2019-09-13-18:01:52, x86-02.bsys.centos.org), qemu version: 2.12.0qemu-kvm-ev-2.12.0-33.1.el7, kernel: 3.10.0-1062.1.2.el7.x86_64, hostname: compute-04.*********
      {{LC_ALL=C }}
      {{PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin }}
      {{QEMU_AUDIO_DRV=none }}
      {{/usr/libexec/qemu-kvm }}
      {{-name guest=r-31-VM,debug-threads=on }}
      {{-S }}
      {{-object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-2-r-31-VM/master-key.aes }}
      {{-machine pc-i440fx-rhel7.6.0,accel=kvm,usb=off,dump-guest-core=off }}
      {{-cpu Westmere-IBRS,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,stibp=on,ssbd=on,pdpe1gb=on,rdtscp=on }}
      {{-m 256 }}
      {{-realtime mlock=off }}
      {{-smp 1,sockets=1,cores=1,threads=1 }}
      {{-uuid c54d8d83-1583-4a8c-9c1e-c5b9cc781cb1 }}
      {{-smbios 'type=1,manufacturer=Apache Software Foundation,product=CloudStack KVM Hypervisor,uuid=c54d8d83-1583-4a8c-9c1e-c5b9cc781cb1' }}
      {{-no-user-config }}
      {{-nodefaults }}
      {{-chardev socket,id=charmonitor,fd=30,server,nowait }}
      {{-mon chardev=charmonitor,id=monitor,mode=control }}
      {{-rtc base=utc }}
      {{-no-shutdown }}
      {{-boot strict=on }}
      {{-device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 }}
      {{-device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x4 }}
      {{-drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/a02545d4-f6d8-4013-ba19-a38b5c63d34a,format=qcow2,if=none,id=drive-virtio-disk0,serial=a02545d4f6d84013ba19,cache=none }}
      {{-device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x5,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2,write-cache=on }}
      {{-drive if=none,id=drive-ide0-1-0,readonly=on }}
      {{-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 }}
      {{-netdev tap,fd=32,id=hostnet0,vhost=on,vhostfd=33 }}
      {{-device virtio-net-pci,netdev=hostnet0,id=net0,mac=0e:00:a9:fe:2a:51,bus=pci.0,addr=0x3,rombar=0,romfile= }}
      {{-netdev tap,fd=34,id=hostnet1,vhost=on,vhostfd=35 }}
      {{-device virtio-net-pci,netdev=hostnet1,id=net1,mac=1e:00:9b:00:03:e1,bus=pci.0,addr=0x7,rombar=0,romfile= }}
      {{-netdev tap,fd=36,id=hostnet2,vhost=on,vhostfd=37 }}
      {{-device virtio-net-pci,netdev=hostnet2,id=net2,mac=02:00:66:ec:00:02,bus=pci.0,addr=0x8,rombar=0,romfile= }}
      {{-chardev pty,id=charserial0 }}
      {{-device isa-serial,chardev=charserial0,id=serial0 }}
      {{-chardev socket,id=charchannel0,fd=38,server,nowait }}
      {{-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 }}
      {{-device usb-tablet,id=input0,bus=usb.0,port=1 }}
      {{-vnc 192.168.145.23:0,password }}
      {{-device cirrus-vga,id=video0,bus=pci.0,addr=0x2 }}
      {{-device i6300esb,id=watchdog0,bus=pci.0,addr=0x6 }}
      {{-watchdog-action none }}
      {{-incoming defer }}
      {{-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny }}
      -msg timestamp=on
      2019-10-18 13:37:47.851+0000: Domain id=2 is tainted: high-privileges
      2019-10-18 13:37:47.851+0000: Domain id=2 is tainted: hook-script
      2019-10-18T13:37:47.987105Z qemu-kvm: -chardev pty,id=charserial0: char device redirected to /dev/pts/2 (label charserial0)
      2019-10-18T13:37:47.987361Z qemu-kvm: -drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/a02545d4-f6d8-4013-ba19-a38b5c63d34a,format=qcow2,if=none,id=drive-virtio-disk0,serial=a02545d4f6d84013ba19,cache=none: 'serial' is deprecated, please use the corresponding option of '-device' instead
      2019-10-18T13:37:48.618909Z qemu-kvm: warning: TSC frequency mismatch between VM (3058974 kHz) and host (3059011 kHz), and TSC scaling unavailable
      warning: Failed to lock byte 100
      warning: Failed to lock byte 100
      2019-10-18 13:37:57.634+0000: shutting down, reason=failed
      2019-10-18T13:37:57.705151Z qemu-kvm: terminating on signal 15 from pid 30295 (/usr/sbin/libvirtd)
      2019-10-18T13:38:00.705148Z qemu-kvm: warning: Failed to lock byte 100
      2019-10-18T13:38:03.705124Z qemu-kvm: warning: Failed to lock byte 100

      I tried to create a new virtual machine on different nodes and different VPC (I tried removing and re-inserting some free KVM node several times into the infrastructure using the management GUI but the result does not change):

      *** MANAGEMENT LOG ***
      ...
      2019-10-18 15:46:31,117 DEBUG [c.c.v.UserVmManagerImpl] (qtp504527234-2144:ctx-77dedc00 ctx-9cad3283) (logid:8fd4205c) Successfully allocated DB entry for VM[User|i-2-73-VM]
      ...
      2019-10-18 15:46:31,285 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp504527234-2144:ctx-77dedc00 ctx-9cad3283) (logid:8fd4205c) submit async job-1724, details: AsyncJobVO {id
      :1724, userId: 5, accountId: 2, instanceType: VirtualMachine, instanceId: 73, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"keyboard":"us","
      iptonetworklist[0].networkid":"8c6a52cf-d3bf-4c8f-8c3a-8d7c302803fa","hostid":"6a994694-9f3a-4dc3-8fde-e8a33e61da08","httpmethod":"GET","templateid":"2d213585-5930-4916-814f
      -f911b4516333","ctxAccountId":"2","uuid":"f08ecf40-521a-4bb8-872d-33d2730ed1e6","domainid":"462ec030-e42b-11e9-958a-441ea1609f9e","cmdEventType":"VM.CREATE","serviceoffering
      id":"134b3a95-7a8e-49b1-95f4-55077c9582ae","response":"json","ctxUserId":"5","hypervisor":"KVM","displayname":"test-new-VM","name":"test-new-VM","zoneid":"64e1c0d5-cd47-439f
      -a9a9-95ccbd02f6b0","ctxStartEventId":"3968","id":"73","ctxDetails":"{\"interface com.cloud.domain.Domain\":\"462ec030-e42b-11e9-958a-441ea1609f9e\",\"interface com.cloud.vm
      .VirtualMachine\":\"f08ecf40-521a-4bb8-872d-33d2730ed1e6\",\"interface com.cloud.dc.DataCenter\":\"64e1c0d5-cd47-439f-a9a9-95ccbd02f6b0\",\"interface com.cloud.template.Virt
      ualMachineTemplate\":\"2d213585-5930-4916-814f-f911b4516333\",\"interface com.cloud.host.Host\":\"6a994694-9f3a-4dc3-8fde-e8a33e61da08\",\"interface com.cloud.offering.Servi
      {{ceOffering\":\"134b3a95-7a8e-49b1-95f4-55077c9582ae\"}","account":"admin","_":"1571403086260"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: }}
      null, initMsid: 74898347171742, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
      2019-10-18 15:46:31,287 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724) (logid:4d1c788d) Executing AsyncJobVO {id:1724, userId: 5, accoun
      tId: 2, instanceType: VirtualMachine, instanceId: 73, cmd: org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin, cmdInfo: {"keyboard":"us","iptonetworklist[0].netwo
      rkid":"8c6a52cf-d3bf-4c8f-8c3a-8d7c302803fa","hostid":"6a994694-9f3a-4dc3-8fde-e8a33e61da08","httpmethod":"GET","templateid":"2d213585-5930-4916-814f-f911b4516333","ctxAccou
      ntId":"2","uuid":"f08ecf40-521a-4bb8-872d-33d2730ed1e6","domainid":"462ec030-e42b-11e9-958a-441ea1609f9e","cmdEventType":"VM.CREATE","serviceofferingid":"134b3a95-7a8e-49b1-
      95f4-55077c9582ae","response":"json","ctxUserId":"5","hypervisor":"KVM","displayname":"test-new-VM","name":"test-new-VM","zoneid":"64e1c0d5-cd47-439f-a9a9-95ccbd02f6b0","ctx
      StartEventId":"3968","id":"73","ctxDetails":"{\"interface com.cloud.domain.Domain\":\"462ec030-e42b-11e9-958a-441ea1609f9e\",\"interface com.cloud.vm.VirtualMachine\":\"f08e
      cf40-521a-4bb8-872d-33d2730ed1e6\",\"interface com.cloud.dc.DataCenter\":\"64e1c0d5-cd47-439f-a9a9-95ccbd02f6b0\",\"interface com.cloud.template.VirtualMachineTemplate\":\"2
      d213585-5930-4916-814f-f911b4516333\",\"interface com.cloud.host.Host\":\"6a994694-9f3a-4dc3-8fde-e8a33e61da08\",\"interface com.cloud.offering.ServiceOffering\":\"134b3a95-
      7a8e-49b1-95f4-55077c9582ae\"}","account":"admin","_":"1571403086260"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 74898347
      171742, completeMsid: null, lastUpdated: null, lastPolled: null, created: null, removed: null}
      ...
      {{2019-10-18 15:46:36,426 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) (logid Seq 22-7912543070313250843: Sending { Cmd , MgmtId: 74898345923166, via: 22, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"2d213585-5930-4916-814f-f911b4516333","uuid":"2d213585-5930-4916-814f-f911b4516333","id":206,"format":"QCOW2","accountId":2,"hvm":false,"displayText":"CentOS-7.7 minimal + tools","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"da06a02e-7aeb-37b9-b14e-fc8a492904fe","id":1,"poolType":"NetworkFilesystem","host":"192.168.145.99","path":"/primary","port":2049,"url":"NetworkFilesystem://192.168.145.99/primary/?ROLE=Primary&STOREUUID=da06a02e-7aeb-37b9-b14e-fc8a492904fe","isManaged":false}},"name":"f3c4caa0-7630-491b-b285-ca14df35ecde","size":32212254720,"hypervisorType":"KVM","bootable":false,"uniqueName":"f3c4caa0-7630-491b-b285-ca14df35ecde","directDownload":false}},"destTO":\{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"8437db21-e0be-4156-93d1-1a968c441c32","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"da06a02e-7aeb-37b9-b14e-fc8a492904fe","id":1,"poolType":"NetworkFilesystem","host":"192.168.145.99","path":"/primary","port":2049,"url":"NetworkFilesystem://192.168.145.99/primary/?ROLE=Primary&STOREUUID=da06a02e-7aeb-37b9-b14e-fc8a492904fe","isManaged":false}},"name":"ROOT-73","size":32212254720,"volumeId":152,"vmName":"i-2-73-VM","accountId":2,"format":"QCOW2","provisioningType":"THIN","id":152,"deviceId":0,"hypervisorType":"KVM"}},"executeInSequence":true,"options":{},"options2":{},"wait":0}}] }}}
      ...
      2019-10-18 15:46:52,838 ERROR [c.c.v.UserVmManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) VM VM[User|i-2-73-VM] unexpectedly went to Stopped state
      2019-10-18 15:46:52,842 DEBUG [c.c.v.UserVmManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Destroying vm VM[User|i-2-73-VM] as it failed to create on Host with Id:22
      2019-10-18 15:46:52,897 DEBUG [c.c.c.CapacityManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null
      2019-10-18 15:46:53,006 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Updating resource Type = volume count for Account = 2 Operation = decreasing Amount = 1
      2019-10-18 15:46:53,032 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Updating resource Type = primary_storage count for Account = 2 Operation = decreasing Amount = 32212254720
      2019-10-18 15:46:53,060 WARN [c.c.a.AlertManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) AlertType:: 8 | dataCenterId:: 1 | podId:: 1 | clusterId:: null | message:: Failed to deploy Vm with Id: 73, on Host with Id: 22
      2019-10-18 15:46:53,104 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Updating resource Type = user_vm count for Account = 2 Operation = decreasing Amount = 1
      2019-10-18 15:46:53,130 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Updating resource Type = cpu count for Account = 2 Operation = decreasing Amount = 2
      2019-10-18 15:46:53,155 DEBUG [c.c.r.ResourceLimitManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Updating resource Type = memory count for Account = 2 Operation = decreasing Amount = 4096
      {{2019-10-18 15:46:53,206 WARN [o.a.c.a.c.a.v.DeployVMCmdByAdmin] (API-Job-Executor-71:ctx-c7b558eb job-1724 ctx-89cdda90) (logid:4d1c788d) Exception: }}
      com.cloud.exception.ConcurrentOperationException: Failed to deploy VM VM[User|i-2-73-VM]
      {{ at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4240)}}
      {{ at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:4222)}}
      {{ at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)}}
      {{ at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)}}
      {{ at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)}}
      {{ at java.lang.reflect.Method.invoke(Method.java:498)}}
      {{ at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)}}
      {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)}}
      {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)}}
      {{ at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:107)}}
      {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)}}
      {{ at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)}}
      {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)}}
      {{ at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)}}
      {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)}}
      {{ at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)}}
      {{ at com.sun.proxy.$Proxy190.startVirtualMachine(Unknown Source)}}
      {{ at org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin.execute(DeployVMCmdByAdmin.java:67)}}
      {{ at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)}}
      {{ at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)}}
      {{ at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:583)}}
      {{ at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)}}
      {{ at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)}}
      {{ at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)}}
      {{ at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:531)}}
      {{ at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)}}
      {{ at java.util.concurrent.FutureTask.run(FutureTask.java:266)}}
      {{ at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)}}
      {{ at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)}}
      {{ at java.lang.Thread.run(Thread.java:748)}}
      2019-10-18 15:46:53,213 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-71:ctx-c7b558eb job-1724) (logid:4d1c788d) Complete async job-1724, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to deploy VM VM[User|i-2-73-VM]"}

      *** QEMU LOG ***
      {{[root@compute-04 qemu]# cat i-2-73-VM.log }}
      2019-10-18 13:46:46.795+0000: starting up libvirt version: 4.5.0, package: 23.el7_7.1 (CentOS BuildSystem <http://bugs.centos.org>, 2019-09-13-18:01:52, x86-02.bsys.centos.org), qemu version: 2.12.0qemu-kvm-ev-2.12.0-33.1.el7, kernel: 3.10.0-1062.1.2.el7.x86_64, hostname: compute-04.*********
      {{LC_ALL=C }}
      {{PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin }}
      {{QEMU_AUDIO_DRV=none }}
      {{/usr/libexec/qemu-kvm }}
      {{-name guest=i-2-73-VM,debug-threads=on }}
      {{-S }}
      {{-object secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-3-i-2-73-VM/master-key.aes }}
      {{-machine pc-i440fx-rhel7.6.0,accel=kvm,usb=off,dump-guest-core=off }}
      {{-cpu Westmere-IBRS,vme=on,ss=on,pclmuldq=on,pcid=on,x2apic=on,tsc-deadline=on,hypervisor=on,arat=on,tsc_adjust=on,stibp=on,ssbd=on,pdpe1gb=on,rdtscp=on }}
      {{-m 4096 }}
      {{-realtime mlock=off }}
      {{-smp 2,sockets=2,cores=1,threads=1 }}
      {{-uuid f08ecf40-521a-4bb8-872d-33d2730ed1e6 }}
      {{-smbios 'type=1,manufacturer=Apache Software Foundation,product=CloudStack KVM Hypervisor,uuid=f08ecf40-521a-4bb8-872d-33d2730ed1e6' }}
      {{-no-user-config }}
      {{-nodefaults }}
      {{-chardev socket,id=charmonitor,fd=29,server,nowait }}
      {{-mon chardev=charmonitor,id=monitor,mode=control }}
      {{-rtc base=utc }}
      {{-no-shutdown }}
      {{-boot strict=on }}
      {{-device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 }}
      {{-device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x4 }}
      {{-drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/8437db21-e0be-4156-93d1-1a968c441c32,format=qcow2,if=none,id=drive-virtio-disk0,serial=8437db21e0be415693d1,cache=none }}
      {{-device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x5,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=2,write-cache=on }}
      {{-drive if=none,id=drive-ide0-1-0,readonly=on }}
      {{-device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 }}
      {{-netdev tap,fd=31,id=hostnet0,vhost=on,vhostfd=32 }}
      {{-device virtio-net-pci,netdev=hostnet0,id=net0,mac=02:00:4c:d3:00:0d,bus=pci.0,addr=0x3 }}
      {{-chardev pty,id=charserial0 }}
      {{-device isa-serial,chardev=charserial0,id=serial0 }}
      {{-chardev socket,id=charchannel0,fd=33,server,nowait }}
      {{-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 }}
      {{-device usb-tablet,id=input0,bus=usb.0,port=1 }}
      {{-vnc 192.168.145.23:0,password }}
      {{-device cirrus-vga,id=video0,bus=pci.0,addr=0x2 }}
      {{-device i6300esb,id=watchdog0,bus=pci.0,addr=0x6 }}
      {{-watchdog-action none }}
      {{-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny }}
      -msg timestamp=on
      2019-10-18 13:46:46.795+0000: Domain id=3 is tainted: high-privileges
      2019-10-18T13:46:46.916615Z qemu-kvm: -chardev pty,id=charserial0: char device redirected to /dev/pts/2 (label charserial0)
      2019-10-18T13:46:46.916853Z qemu-kvm: -drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/8437db21-e0be-4156-93d1-1a968c441c32,format=qcow2,if=none,id=drive-virtio-disk0,serial=8437db21e0be415693d1,cache=none: 'serial' is deprecated, please use the corresponding option of '-device' instead
      2019-10-18T13:46:49.930257Z qemu-kvm: -drive file=/mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe/8437db21-e0be-4156-93d1-1a968c441c32,format=qcow2,if=none,id=drive-virtio-disk0,serial=8437db21e0be415693d1,cache=none: Failed to lock byte 100
      2019-10-18 13:46:49.944+0000: shutting down, reason=failed

       

      From my research of the past few days it would seem a problem that revolves around: qcow2 + qemu + NFS / gluster.

      I add the details of the NFS mount (mount done by Cloudstack-management when registering the node in the infrastructure - not manually by me).
      [root@compute-04 ~]# mount | grep primary
      192.168.145.99:/primary on /mnt/da06a02e-7aeb-37b9-b14e-fc8a492904fe type nfs (rw,nosuid,nodev,noexec,relatime,sync,vers=3,rsize=1048576,wsize=1048576,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,noac,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=192.168.145.99,mountvers=3,mountport=38785,mountproto=tcp,local_lock=none,addr=192.168.145.99)

      I couldn't find a solution by myself.
      I hope some of you can help me. Many thanks in advance.

      Enzo Martino

      Attachments

        Activity

          People

            Unassigned Unassigned
            marvin5808 Enzo Martino
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated: