shweta agarwal created CLOUDSTACK-7251:
------------------------------------------
Summary: [LXC] VM installation fails when using local storage as
primary storage
Key: CLOUDSTACK-7251
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7251
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: KVM
Affects Versions: 4.5.0
Reporter: shweta agarwal
Priority: Blocker
Fix For: 4.5.0
Repro steps:
Create a LXC setup with local storage enabled
create a service offering with local storage
create a VM with theta service offering
Bug:
VM creation error out
MS log shows :
2014-08-05 05:01:56,832 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Seq
1-8575416640466846714: Sending { Cmd , MgmtId: 233845177509765, via:
1(Rack1Pod1Host23), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StartCommand":{"vm":{"id":17,"name":"i-2-17-VM","type":"User","cpus":1,"minSpeed":128,"maxSpeed":128,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","platformEmulator":"Other","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"f7a4e3e8e4fec4f9","params":{},"uuid":"5cfab85b-ceae-4df0-ac0e-a07a84bda843","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b021367-8870-495f-93b0-f28e3d0e86d7","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2bbf9d08-b442-4a87-9f26-41d39679747b","id":3,"poolType":"Filesystem","host":"10.147.40.23","path":"/var/lib/libvirt/images","port":0,"url":"Filesystem://10.147.40.23/var/lib/libvirt/images/?ROLE=Primary&STOREUUID=2bbf9d08-b442-4a87-9f26-41d39679747b"}},"name":"ROOT-17","size":0,"path":"0b021367-8870-495f-93b0-f28e3d0e86d7","volumeId":18,"vmName":"i-2-17-VM","accountId":2,"provisioningType":"THIN","id":18,"deviceId":0,"hypervisorType":"LXC"}},"diskSeq":0,"path":"0b021367-8870-495f-93b0-f28e3d0e86d7","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"10.147.40.23","volumeSize":"0"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"065d160a-9bd8-4d34-b9ea-655014468157","uuid":"675b6a8c-2ab1-4ea1-bf20-3ddd910b9ecd","ip":"10.1.1.232","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:4a:e1:00:0b","dns1":"10.140.50.6","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1046","isolationUri":"vlan://1046","isSecurityGroupEnabled":false}]},"hostIp":"10.147.40.23","executeInSequence":false,"wait":0}}]
}
2014-08-05 05:01:57,272 DEBUG [c.c.a.ApiServlet]
(catalina-exec-21:ctx-3c782bac) ===START=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=80f71511-b142-4d46-8108-697905b62179&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229318792
2014-08-05 05:01:57,332 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-3c782bac
ctx-2802cc3d) ===END=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=80f71511-b142-4d46-8108-697905b62179&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229318792
2014-08-05 05:01:57,355 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-a0a21868) HostStatsCollector is running...
2014-08-05 05:01:57,361 WARN [o.a.c.f.j.AsyncJobExecutionContext]
(StatsCollector-1:ctx-a0a21868) Job is executed without a context, setup psudo
job for the executing thread
2014-08-05 05:01:58,006 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-a0a21868)
Seq 1-8575416640466846715: Received: { Ans: , MgmtId: 233845177509765, via: 1,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-08-05 05:01:58,059 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Resetting hosts suitable for reconnect
2014-08-05 05:01:58,060 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Completed resetting hosts suitable for reconnect
2014-08-05 05:01:58,060 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Acquiring hosts for clusters already owned by this
management server
2014-08-05 05:01:58,061 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Completed acquiring hosts for clusters already owned by
this management server
2014-08-05 05:01:58,061 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Acquiring hosts for clusters not owned by any management
server
2014-08-05 05:01:58,061 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager
Timer:ctx-599ebf73) Completed acquiring hosts for clusters not owned by any
management server
2014-08-05 05:01:58,454 DEBUG [c.c.a.ApiServlet]
(catalina-exec-22:ctx-c32fe384) ===START=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=89d5fe9f-9df3-4c03-b945-e6e2f6c1972f&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229319989
2014-08-05 05:01:58,516 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-c32fe384
ctx-a02236b5) ===END=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=89d5fe9f-9df3-4c03-b945-e6e2f6c1972f&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229319989
2014-08-05 05:01:58,542 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-a0a21868)
Seq 4-7841329901205455611: Received: { Ans: , MgmtId: 233845177509765, via: 4,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-08-05 05:01:58,943 DEBUG [c.c.a.t.Request] (AgentManager-Handler-7:null)
Seq 1-8575416640466846714: Processing: { Ans: , MgmtId: 233845177509765, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":17,"name":"i-2-17-VM","type":"User","cpus":1,"minSpeed":128,"maxSpeed":128,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","platformEmulator":"Other","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"f7a4e3e8e4fec4f9","vncAddr":"10.147.40.23","params":{},"uuid":"5cfab85b-ceae-4df0-ac0e-a07a84bda843","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0b021367-8870-495f-93b0-f28e3d0e86d7","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2bbf9d08-b442-4a87-9f26-41d39679747b","id":3,"poolType":"Filesystem","host":"10.147.40.23","path":"/var/lib/libvirt/images","port":0,"url":"Filesystem://10.147.40.23/var/lib/libvirt/images/?ROLE=Primary&STOREUUID=2bbf9d08-b442-4a87-9f26-41d39679747b"}},"name":"ROOT-17","size":0,"path":"0b021367-8870-495f-93b0-f28e3d0e86d7","volumeId":18,"vmName":"i-2-17-VM","accountId":2,"provisioningType":"THIN","id":18,"deviceId":0,"hypervisorType":"LXC"}},"diskSeq":0,"path":"0b021367-8870-495f-93b0-f28e3d0e86d7","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"10.147.40.23","volumeSize":"0"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"065d160a-9bd8-4d34-b9ea-655014468157","uuid":"675b6a8c-2ab1-4ea1-bf20-3ddd910b9ecd","ip":"10.1.1.232","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:4a:e1:00:0b","dns1":"10.140.50.6","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1046","isolationUri":"vlan://1046","isSecurityGroupEnabled":false}]},"result":false,"details":"internal
error guest failed to start: 2014-08-05 09:01:58.436+0000: 1069: info :
libvirt version: 0.9.10, package: 21.el6 (Red Hat, Inc.
<http://bugzilla.redhat.com/bugzilla>, 2012-05-23-09:15:11,
x86-003.build.bos.redhat.com)\n2014-08-05 09:01:58.436+0000: 1069: error :
lxcControllerRun:1484 : Failed to query file context on
/var/lib/libvirt/images/0b021367-8870-495f-93b0-f28e3d0e86d7: No data
available\n","wait":0}}] }
2014-08-05 05:01:58,943 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Seq
1-8575416640466846714: Received: { Ans: , MgmtId: 233845177509765, via: 1,
Ver: v1, Flags: 10, { StartAnswer } }
2014-08-05 05:01:58,996 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Unable to
start VM on Host[-1-Routing] due to internal error guest failed to start:
2014-08-05 09:01:58.436+0000: 1069: info : libvirt version: 0.9.10, package:
21.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>,
2012-05-23-09:15:11, x86-003.build.bos.redhat.com)
2014-08-05 09:01:58.436+0000: 1069: error : lxcControllerRun:1484 : Failed to
query file context on
/var/lib/libvirt/images/0b021367-8870-495f-93b0-f28e3d0e86d7: No data available
2014-08-05 05:01:59,047 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Cleaning up
resources for the vm VM[User|i-2-17-VM] in Starting state
2014-08-05 05:01:59,051 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Seq
1-8575416640466846716: Sending { Cmd , MgmtId: 233845177509765, via:
1(Rack1Pod1Host23), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-17-VM","wait":0}}]
}
2014-08-05 05:01:59,678 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-29d59690)
===START=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=a91ae93e-1784-4910-825d-7f0ef9156fba&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229321213
2014-08-05 05:01:59,742 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-29d59690
ctx-dc6257af) ===END=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=a91ae93e-1784-4910-825d-7f0ef9156fba&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229321213
2014-08-05 05:01:59,786 DEBUG [c.c.a.t.Request] (AgentManager-Handler-14:null)
Seq 1-8575416640466846716: Processing: { Ans: , MgmtId: 233845177509765, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2014-08-05 05:01:59,787 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Seq
1-8575416640466846716: Received: { Ans: , MgmtId: 233845177509765, via: 1,
Ver: v1, Flags: 10, { StopAnswer } }
2014-08-05 05:01:59,794 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Service
SecurityGroup is not supported in the network id=209
2014-08-05 05:01:59,795 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Changing
active number of nics for network id=209 on -1
2014-08-05 05:01:59,867 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Asking
VirtualRouter to release
NicProfile[31-17-4299d998-ebbe-4af2-9c13-4f6a73ed06bb-10.1.1.232-null
2014-08-05 05:01:59,867 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Successfully
released network resources for the vm VM[User|i-2-17-VM]
2014-08-05 05:01:59,867 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Successfully
cleanued up resources for the vm VM[User|i-2-17-VM] in Starting state
2014-08-05 05:01:59,870 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Root volume is
ready, need to place VM in volume's cluster
2014-08-05 05:01:59,876 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Deploy avoids
pods: [], clusters: [], hosts: [1]
2014-08-05 05:01:59,877 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@20dca265
2014-08-05 05:01:59,877 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
128, requested ram: 134217728
2014-08-05 05:01:59,877 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Is ROOT volume
READY (pool already allocated)?: Yes
2014-08-05 05:01:59,877 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) DeploymentPlan
has host_id specified, choosing this host and making no checks on this host: 1
2014-08-05 05:01:59,878 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) The specified
host is in avoid set
2014-08-05 05:01:59,878 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Cannnot deploy
to specified host, returning.
2014-08-05 05:02:00,072 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's original
host id: null new host id: null host id before state transition: 1
2014-08-05 05:02:00,077 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Hosts's actual
total CPU: 12404 and CPU after applying overprovisioning: 12404
2014-08-05 05:02:00,077 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Hosts's actual
total RAM: 8244576256 and RAM after applying overprovisioning: 8244576256
2014-08-05 05:02:00,077 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) release cpu
from host: 1, old used: 3128,reserved: 0, actual total: 12404, total with
overprovisioning: 12404; new used: 3000,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2014-08-05 05:02:00,077 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) release mem
from host: 1, old used: 3489660928,reserved: 0, total: 8244576256; new used:
3355443200,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-08-05 05:02:00,140 DEBUG [c.c.a.ApiServlet]
(catalina-exec-24:ctx-d16fd087) ===START=== 10.146.0.131 -- GET
command=queryAsyncJobResult&jobId=e170b81d-1560-4985-bc91-5284c16dd555&response=json&sessionkey=X745JY%2BC0rOgkt4Sbx3muCB1eJQ%3D&_=1407229321674
2014-08-05 05:02:00,207 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Invocation
exception, caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-2-17-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2014-08-05 05:02:00,207 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201 ctx-1f8afb7d) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-17-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2014-08-05 05:02:00,207 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201) Done with run of VM work
job: com.cloud.vm.VmWorkStart for VM 17, job origin: 200
2014-08-05 05:02:00,207 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201) Unable to complete
AsyncJobVO {id:201, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAEXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 233845177509765, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Tue Aug 05 05:01:29 EDT 2014}, job origin:200
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-17-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:933)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4582)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4738)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
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:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
2014-08-05 05:02:00,212 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-17:ctx-66f0332c job-200/job-201) Complete async job-201,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItMTctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAOc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABTnQAJGphdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2skU3luY3QAD0Z1dHVyZVRhc2suamF2YXQACGlubmVyUnVuc3EAfgALAAAApnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2txAH4AKXEAfgAXc3EAfgALAAAEVnQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACW3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4AL3EAfgAXc3EAfgALAAAC0nQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AO3g
@
Agent log shows :
<domain type='lxc'>
<name>i-2-19-VM</name>
<uuid>ff35d8a0-7f2f-49a9-81f4-da73bc88613a</uuid>
<description>CentOS 6.4 (64-bit)</description>
<clock offset='utc'>
<timer name='kvmclock' tickpolicy='catchup' >
</timer>
</clock>
<features>
<pae/>
<apic/>
<acpi/>
</features>
<devices>
<emulator></emulator>
<interface type='bridge'>
<source bridge='brem1-1046'/>
<mac address='02:00:54:28:00:0d'/>
<model type='e1000'/>
<bandwidth>
<inbound average='25600' peak='25600'/>
<outbound average='25600' peak='25600'/>
</bandwidth>
</interface>
<filesystem type='mount'>
<source dir='/var/lib/libvirt/images/8abd03f0-9f5e-41a1-9f59-b951b1baca7e'/>
<target dir='/'/>
</filesystem>
<serial type='pty'>
<target port='0'/>
</serial>
<console type='pty'>
<target port='0'/>
</console>
</devices>
<memory>131072</memory>
<devices>
<memballoon model='none'/>
</devices>
<vcpu>1</vcpu>
<os>
<type>exe</type>
<init>/sbin/init</init>
</os>
<cputune>
<shares>128</shares>
</cputune>
<cpu></cpu><on_reboot>restart</on_reboot>
<on_poweroff>destroy</on_poweroff>
<on_crash>destroy</on_crash>
</domain>
2014-08-05 05:24:56,623 WARN [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-5:null) LibvirtException
org.libvirt.LibvirtException: internal error guest failed to start: 2014-08-05
09:24:56.472+0000: 3090: info : libvirt version: 0.9.10, package: 21.el6 (Red
Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2012-05-23-09:15:11,
x86-003.build.bos.redhat.com)
2014-08-05 09:24:56.472+0000: 3090: error : lxcControllerRun:1484 : Failed to
query file context on
/var/lib/libvirt/images/8abd03f0-9f5e-41a1-9f59-b951b1baca7e: No data available
at org.libvirt.ErrorHandler.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.Connect.processError(Unknown Source)
at org.libvirt.Connect.domainCreateXML(Unknown Source)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.startVM(LibvirtComputingResource.java:1238)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.execute(LibvirtComputingResource.java:3767)
at
com.cloud.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtComputingResource.java:1332)
at com.cloud.agent.Agent.processRequest(Agent.java:501)
at com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.java:808)
at com.cloud.utils.nio.Task.run(Task.java:84)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
2014-08-05 05:24:56,624 DEBUG [kvm.storage.KVMStoragePoolManager]
(agentRequest-Handler-5:null) Disconnecting disk
8abd03f0-9f5e-41a1-9f59-b951b1baca7e
2014-08-05 05:24:56,624 DEBUG [kvm.storage.LibvirtStorageAdaptor]
(agentRequest-Handler-5:null) Trying to fetch storage pool
2bbf9d08-b442-4a87-9f26-41d39679747b from libvirt
2014-08-05 05:24:56,639 DEBUG [cloud.agent.Agent] (agentRequest-Handler-5:null)
Seq 1-8575416640466846834: { Ans: , MgmtId: 233845177509765, via: 1, Ver: v1,
Flags: 10,
[{"com.cloud.agent.api.StartAnswer":{"vm":{"id":19,"name":"i-2-19-VM","type":"User","cpus":1,"minSpeed":128,"maxSpeed":128,"minRam":134217728,"maxRam":134217728,"arch":"x86_64","os":"CentOS
6.4
(64-bit)","platformEmulator":"Other","bootArgs":"","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"e7a3dee2600e3054","vncAddr":"10.147.40.23","params":{"Message.ReservedCapacityFreed.Flag":"false"},"uuid":"ff35d8a0-7f2f-49a9-81f4-da73bc88613a","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"8abd03f0-9f5e-41a1-9f59-b951b1baca7e","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2bbf9d08-b442-4a87-9f26-41d39679747b","id":3,"poolType":"Filesystem","host":"10.147.40.23","path":"/var/lib/libvirt/images","port":0,"url":"Filesystem://10.147.40.23/var/lib/libvirt/images/?ROLE=Primary&STOREUUID=2bbf9d08-b442-4a87-9f26-41d39679747b"}},"name":"ROOT-19","size":0,"path":"8abd03f0-9f5e-41a1-9f59-b951b1baca7e","volumeId":20,"vmName":"i-2-19-VM","accountId":2,"provisioningType":"THIN","id":20,"deviceId":0,"hypervisorType":"LXC"}},"diskSeq":0,"path":"8abd03f0-9f5e-41a1-9f59-b951b1baca7e","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"10.147.40.23","volumeSize":"0"}},{"data":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"id":0,"format":"ISO","accountId":0,"hvm":false}},"diskSeq":3,"type":"ISO"}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"pxeDisable":false,"nicUuid":"7481d036-9af3-4632-8180-365e2e7ac5ce","uuid":"675b6a8c-2ab1-4ea1-bf20-3ddd910b9ecd","ip":"10.1.1.184","netmask":"255.255.255.0","gateway":"10.1.1.1","mac":"02:00:54:28:00:0d","dns1":"10.140.50.6","dns2":"","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://1046","isolationUri":"vlan://1046","isSecurityGroupEnabled":false}]},"result":false,"details":"internal
error guest failed to start: 2014-08-05 09:24:56.472+0000: 3090: info :
libvirt version: 0.9.10, package: 21.el6 (Red Hat, Inc.
<http://bugzilla.redhat.com/bugzilla>, 2012-05-23-09:15:11,
x86-003.build.bos.redhat.com)\n2014-08-05 09:24:56.472+0000: 3090: error :
lxcControllerRun:1484 : Failed to query file context on
/var/lib/libvirt/images/8abd03f0-9f5e-41a1-9f59-b951b1baca7e: No data
available\n","wait":0}}] }
2014-08-05 05:24:56,747 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Request:Seq 1-8575416640466846835: { Cmd , MgmtId: 233845177509765, via: 1,
Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-19-VM","wait":0}}]
}
2014-08-05 05:24:56,747 DEBUG [cloud.agent.Agent] (agentRequest-Handler-4:null)
Processing command: com.cloud.agent.api.StopCommand
2014-08-05 05:24:56,749 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) can't find connection: KVM, for vm: i-2-19-VM,
continue
2014-08-05 05:24:56,751 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) can't find connection: LXC, for vm: i-2-19-VM,
continue
2014-08-05 05:24:56,751 DEBUG [kvm.resource.LibvirtConnection]
(agentRequest-Handler-4:null) can't find which hypervisor the vm used , then
use the default hypervisor
2014-08-05 05:24:56,753 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Failed to get dom xml:
org.libvirt.LibvirtException: Domain not found: No domain with matching name
'i-2-19-VM'
2014-08-05 05:24:56,755 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Failed to get dom xml:
org.libvirt.LibvirtException: Domain not found: No domain with matching name
'i-2-19-VM'
2014-08-05 05:24:56,756 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Failed to get dom xml:
org.libvirt.LibvirtException: Domain not found: No domain with matching name
'i-2-19-VM'
2014-08-05 05:24:56,756 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Executing:
/usr/share/cloudstack-common/scripts/vm/network/security_group.py
destroy_network_rules_for_vm --vmname i-2-19-VM
2014-08-05 05:24:56,882 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Execution is successful.
2014-08-05 05:24:56,882 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) Try to stop the vm at first
2014-08-05 05:24:56,884 DEBUG [kvm.resource.LibvirtComputingResource]
(agentRequest-Handler-4:null) VM i-2-19-VM doesn't exist, no need to stop it
--
This message was sent by Atlassian JIRA
(v6.2#6252)
