Enzo Martino created CLOUDSTACK-10412:
-----------------------------------------
Summary: starting or moving VMs to new KVM Host fails with qemu
error "Failed to lock byte 100" - Cloudstack 4.13.0
Key: CLOUDSTACK-10412
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-10412
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: KVM
Environment: OS management server: centos-release-7-7.1908.0.el7
OS KVM host compute: centos-release-7-7.1908.0.el7
Hypervisor: KVM
Cloudstack Release: 4.13.0
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
Zone Type: Advanced zone
QEMU version: qemu-kvm-ev-2.12.0-33.1.el7
Libvirt version: libvirt-4.5.0-23.el7_7
Reporter: Enzo Martino
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
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
