You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Kishan Kavala (JIRA)" <ji...@apache.org> on 2014/09/01 07:48:20 UTC
[jira] [Updated] (CLOUDSTACK-7251) [LXC] VM installation fails when
using local storage as primary storage
[ https://issues.apache.org/jira/browse/CLOUDSTACK-7251?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kishan Kavala updated CLOUDSTACK-7251:
--------------------------------------
Priority: Major (was: Blocker)
> [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
> Assignee: Kishan Kavala
> 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.3.4#6332)