Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 23FE9F9F2 for ; Mon, 6 May 2013 16:36:16 +0000 (UTC) Received: (qmail 89333 invoked by uid 500); 6 May 2013 16:36:16 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 89312 invoked by uid 500); 6 May 2013 16:36:15 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 89304 invoked by uid 500); 6 May 2013 16:36:15 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 89301 invoked by uid 99); 6 May 2013 16:36:15 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 06 May 2013 16:36:15 +0000 Date: Mon, 6 May 2013 16:36:15 +0000 (UTC) From: "Chip Childers (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-2322) 2.2.14 to 4.1.0 upgrade: unable to add a new VM MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-2322?page=3Dcom.atl= assian.jira.plugin.system.issuetabpanels:all-tabpanel ] Chip Childers updated CLOUDSTACK-2322: -------------------------------------- Assignee: Wei Zhou =20 > 2.2.14 to 4.1.0 upgrade: unable to add a new VM=20 > ------------------------------------------------ > > Key: CLOUDSTACK-2322 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-232= 2 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: KVM > Affects Versions: 4.1.0 > Environment: CentOS 6.4=20 > Reporter: Shashi Dahal > Assignee: Wei Zhou > Priority: Critical > Fix For: 4.1.0 > > > Hi,=20 > After upgrade from 2.2.14 to 4.1.0 , i tried to add a new VM, which fails= .=20 > Logs attached.=20 > 2013-05-03 12:41:37,400 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistVirtualMachin= es&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&listAl= l=3Dtrue&page=3D1&pagesize=3D20&_=3D1367577697419 > 2013-05-03 12:41:37,440 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistVirtualMachines= &response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&listAll= =3Dtrue&page=3D1&pagesize=3D20&_=3D1367577697419 > 2013-05-03 12:41:39,363 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistZones&availabl= e=3Dtrue&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&= _=3D1367577699385 > 2013-05-03 12:41:39,384 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl= ] (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet > 2013-05-03 12:41:39,390 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistZones&available= =3Dtrue&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_= =3D1367577699385 > 2013-05-03 12:41:40,175 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:41:40,177 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:41:40,193 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:41:40,196 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:41:40,774 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistHypervisors&zo= neid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=3Djson&sessionkey=3DeX= FmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577700796 > 2013-05-03 12:41:40,791 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistHypervisors&zone= id=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&response=3Djson&sessionkey=3DeXFm= gvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577700796 > 2013-05-03 12:41:40,801 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&temp= latefilter=3Dfeatured&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&respons= e=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D136757770082= 2 > 2013-05-03 12:41:40,878 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&templa= tefilter=3Dfeatured&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&response= =3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577700822 > 2013-05-03 12:41:40,886 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&tem= platefilter=3Dcommunity&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&respo= nse=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577700= 909 > 2013-05-03 12:41:40,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&templ= atefilter=3Dcommunity&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&respons= e=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D136757770090= 9 > 2013-05-03 12:41:40,921 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&temp= latefilter=3Dselfexecutable&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&r= esponse=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D136757= 7700943 > 2013-05-03 12:41:40,975 DEBUG [cloud.server.StatsCollector] (StatsCollect= or-3:null) StorageCollector is running... > 2013-05-03 12:41:41,002 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistTemplates&templa= tefilter=3Dselfexecutable&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&res= ponse=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D13675777= 00943 > 2013-05-03 12:41:41,033 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 6-685442215: Received: { Ans: , MgmtId: 90520747364525, via: 6,= Ver: v1, Flags: 10, { GetStorageStatsAnswer } } > 2013-05-03 12:41:41,140 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 2-1920335887: Received: { Ans: , MgmtId: 90520747364525, via: 2= , Ver: v1, Flags: 10, { GetStorageStatsAnswer } } > 2013-05-03 12:41:42,116 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistServiceOfferi= ngs&issystem=3Dfalse&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2= BaLMM3DI%3D&_=3D1367577702138 > 2013-05-03 12:41:42,128 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistServiceOffering= s&issystem=3Dfalse&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2Ba= LMM3DI%3D&_=3D1367577702138 > 2013-05-03 12:41:43,234 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistDiskOfferings&= response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D13675= 77703256 > 2013-05-03 12:41:43,253 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistDiskOfferings&re= sponse=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577= 703256 > 2013-05-03 12:41:44,447 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:nul= l) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistVPCs&response= =3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577704469 > 2013-05-03 12:41:44,461 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:nul= l) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistVPCs&response=3D= json&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577704469 > 2013-05-03 12:41:44,470 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistNetworks&resp= onse=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&zoneId=3D54fc= b292-09d8-4aad-b0e2-0dacd59408d0&canusefordeploy=3Dtrue&type=3DShared&domai= nid=3D1&account=3Dadmin&_=3D1367577704492 > 2013-05-03 12:41:44,483 DEBUG [cloud.user.AccountManagerImpl] (catalina-e= xec-17:null) Access granted to Acct[2-admin] to Domain:1/ by DomainChecker_= EnhancerByCloudStack_a8431b6f > 2013-05-03 12:41:44,519 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistNetworks&respon= se=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&zoneId=3D54fcb2= 92-09d8-4aad-b0e2-0dacd59408d0&canusefordeploy=3Dtrue&type=3DShared&domaini= d=3D1&account=3Dadmin&_=3D1367577704492 > 2013-05-03 12:41:44,530 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistNetworkOfferi= ngs&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&forvp= c=3Dfalse&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&guestiptype=3DIsola= ted&supportedServices=3DSourceNat&specifyvlan=3Dfalse&state=3DEnabled&_=3D1= 367577704551 > 2013-05-03 12:41:44,566 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistNetworkOffering= s&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&forvpc= =3Dfalse&zoneid=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&guestiptype=3DIsolat= ed&supportedServices=3DSourceNat&specifyvlan=3Dfalse&state=3DEnabled&_=3D13= 67577704551 > 2013-05-03 12:41:46,386 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistSecurityGroup= s&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&domaini= d=3D1&account=3Dadmin&_=3D1367577706407 > 2013-05-03 12:41:46,400 DEBUG [cloud.user.AccountManagerImpl] (catalina-e= xec-18:null) Access granted to Acct[2-admin] to Domain:1/ by DomainChecker_= EnhancerByCloudStack_a8431b6f > 2013-05-03 12:41:46,413 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistSecurityGroups&= response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&domainid= =3D1&account=3Dadmin&_=3D1367577706407 > 2013-05-03 12:41:54,529 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DdeployVirtualMach= ine&zoneId=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&templateId=3D202&hypervis= or=3DKVM&serviceOfferingId=3D2&securitygroupids=3D1&networkIds=3D203&displa= yname=3DMY-VM&name=3DMY-VM&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2B= K%2B%2BaLMM3DI%3D&_=3D1367577714552 > 2013-05-03 12:41:54,540 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11= :null) InfrastructureEntity name is:com.cloud.offering.ServiceOffering > 2013-05-03 12:41:54,541 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11= :null) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate > 2013-05-03 12:41:54,544 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11= :null) ControlledEntity name is:com.cloud.network.Network > 2013-05-03 12:41:54,548 DEBUG [cloud.api.ApiDispatcher] (catalina-exec-11= :null) ControlledEntity name is:com.cloud.network.security.SecurityGroup > 2013-05-03 12:41:54,607 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec= -11:null) Allocating in the DB for vm > 2013-05-03 12:41:54,623 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catal= ina-exec-11:null) Allocating entries for VM: VM[User|MY-VM] > 2013-05-03 12:41:54,624 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catal= ina-exec-11:null) Allocating nics for VM[User|MY-VM] > 2013-05-03 12:41:54,625 DEBUG [cloud.network.NetworkManagerImpl] (catalin= a-exec-11:null) Allocating nic for vm VM[User|MY-VM] in network Ntwk[203|Gu= est|5] with requested profile NicProfile[0-0-null-null-null > 2013-05-03 12:41:54,637 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catal= ina-exec-11:null) Allocaing disks for VM[User|MY-VM] > 2013-05-03 12:41:54,649 DEBUG [cloud.vm.VirtualMachineManagerImpl] (catal= ina-exec-11:null) Allocation completed for VM: VM[User|MY-VM] > 2013-05-03 12:41:54,649 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec= -11:null) Successfully allocated DB entry for VM[User|MY-VM] > 2013-05-03 12:41:54,776 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-11:null) submit async job-33, details: AsyncJobVO {id:33, userId: 2, = accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 1= 7, cmd: org.apache.cloudstack.api.command.user.vm.DeployVMCmd, cmdOriginato= r: null, cmdInfo: {"sessionkey":"eXFmgvJpWd7KmHo0+K++aLMM3DI\u003d","ctxUse= rId":"2","serviceOfferingId":"2","securitygroupids":"1","zoneId":"54fcb292-= 09d8-4aad-b0e2-0dacd59408d0","templateId":"202","response":"json","id":"17"= ,"networkIds":"203","hypervisor":"KVM","name":"MY-VM","_":"1367577714552","= ctxAccountId":"2","ctxStartEventId":"228","displayname":"MY-VM"}, cmdVersio= n: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, = resultCode: 0, result: null, initMsid: 90520747364525, completeMsid: null, = lastUpdated: null, lastPolled: null, created: null} > 2013-05-03 12:41:54,778 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-24:job-33) Executing org.apache.cloudstack.api.command.user.vm.DeployV= MCmd for job-33 > 2013-05-03 12:41:54,780 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DdeployVirtualMachin= e&zoneId=3D54fcb292-09d8-4aad-b0e2-0dacd59408d0&templateId=3D202&hypervisor= =3DKVM&serviceOfferingId=3D2&securitygroupids=3D1&networkIds=3D203&displayn= ame=3DMY-VM&name=3DMY-VM&response=3Djson&sessionkey=3DeXFmgvJpWd7KmHo0%2BK%= 2B%2BaLMM3DI%3D&_=3D1367577714552 > 2013-05-03 12:41:54,783 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-24:= job-33) InfrastructureEntity name is:com.cloud.offering.ServiceOffering > 2013-05-03 12:41:54,784 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-24:= job-33) ControlledEntity name is:com.cloud.template.VirtualMachineTemplate > 2013-05-03 12:41:54,785 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-24:= job-33) ControlledEntity name is:com.cloud.network.Network > 2013-05-03 12:41:54,788 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-24:= job-33) ControlledEntity name is:com.cloud.network.security.SecurityGroup > 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) DeploymentPlanner allocation algorithm: userconcentratedpod_ra= ndom > 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Trying to allocate a host and storage pools from dc:1, pod:nul= l,cluster:null, requested cpu: 1000, requested ram: 1073741824 > 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Is ROOT volume READY (pool already allocated)?: No > 2013-05-03 12:41:54,861 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Searching all possible resources under this Zone: 1 > 2013-05-03 12:41:54,865 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Listing clusters in order of aggregate capacity, that have (at= least one host with) enough CPU and RAM capacity under this Zone: 1 > 2013-05-03 12:41:54,867 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) CPUOverprovisioningFactor considered: 10.0 > 2013-05-03 12:41:54,877 DEBUG [cloud.deploy.UserConcentratedPodPlanner] (= Job-Executor-24:job-33) Applying UserConcentratedPod heuristic for account:= 2 > 2013-05-03 12:41:54,879 DEBUG [cloud.deploy.UserConcentratedPodPlanner] (= Job-Executor-24:job-33) Reordering cluster list as per pods ordered by user= concentration > 2013-05-03 12:41:54,892 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Checking resources in Cluster: 1 under Pod: 1 > 2013-05-03 12:41:54,894 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1= cluster:1 > 2013-05-03 12:41:54,897 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) FirstFitAllocator has 2 hosts to = check for allocation: [Host[-5-Routing], Host[-2-Routing]] > 2013-05-03 12:41:54,904 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Found 2 hosts for allocation afte= r prioritization: [Host[-5-Routing], Host[-2-Routing]] > 2013-05-03 12:41:54,904 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Looking for speed=3D1000Mhz, Ram= =3D1024 > 2013-05-03 12:41:54,908 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Checking if host: 5 has enough = capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverpro= visioningFactor: 1.0 > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Hosts's actual total CPU: 20216= and CPU after applying overprovisioning: 20216 > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Free CPU: 15716 , Requested CPU= : 1000 > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Free RAM: 13760352256 , Request= ed RAM: 1073741824 > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Host has enough CPU and RAM ava= ilable > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc CPU from host:= 5, used: 4500, reserved: 0, actual total: 20216, total with overprovisioni= ng: 20216; requested cpu:1000,alloc_from_last_host?:false ,considerReserved= Capacity?: true > 2013-05-03 12:41:54,912 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc MEM from host:= 5, used: 2952790016, reserved: 0, total: 16713142272; requested mem: 10737= 41824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2013-05-03 12:41:54,913 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Found a suitable host, adding to = list: 5 > 2013-05-03 12:41:54,916 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Checking if host: 2 has enough = capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverpro= visioningFactor: 1.0 > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Hosts's actual total CPU: 20216= and CPU after applying overprovisioning: 20216 > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Free CPU: 19216 , Requested CPU= : 1000 > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Free RAM: 15505182720 , Request= ed RAM: 1073741824 > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) Host has enough CPU and RAM ava= ilable > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc CPU from host:= 2, used: 1000, reserved: 0, actual total: 20216, total with overprovisioni= ng: 20216; requested cpu:1000,alloc_from_last_host?:false ,considerReserved= Capacity?: true > 2013-05-03 12:41:54,921 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33 FirstFitRoutingAllocator) STATS: Can alloc MEM from host:= 2, used: 1207959552, reserved: 0, total: 16713142272; requested mem: 10737= 41824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2013-05-03 12:41:54,921 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Found a suitable host, adding to = list: 2 > 2013-05-03 12:41:54,921 DEBUG [allocator.impl.FirstFitAllocator] (Job-Exe= cutor-24:job-33 FirstFitRoutingAllocator) Host Allocator returning 2 suitab= le hosts > 2013-05-03 12:41:54,924 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Checking suitable pools for volume (Id, Type): (20,ROOT) > 2013-05-03 12:41:54,924 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) We need to allocate new storagepool for this volume > 2013-05-03 12:41:54,926 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Calling StoragePoolAllocators to find suitable pools > 2013-05-03 12:41:54,928 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) Looking for pools in dc: 1 pod:1 cluster:1 > 2013-05-03 12:41:54,930 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) FirstFitStoragePoolAllocator has 1 pools to = check for allocation > 2013-05-03 12:41:54,930 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Checking if storage pool is suitable, name: = PRIMARY ,poolId: 200 > 2013-05-03 12:41:54,930 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Is localStorageAllocationNeeded? false > 2013-05-03 12:41:54,931 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Is storage pool shared? true > 2013-05-03 12:41:54,935 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-24:job-33) Checking pool 200 for storage, totalSize: 7999230836736, u= sedBytes: 452555964416, usedPct: 0.056574934972205476, disable threshold: 0= .85 > 2013-05-03 12:41:54,944 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-24:job-33) Checking pool: 200 for volume allocation [Vol[20|vm=3D17|R= OOT]], maxSize : 15998461673472, totalAllocatedSize : 266014556160, askingS= ize : 42949672960, allocated disable threshold: 0.85 > 2013-05-03 12:41:54,945 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) FirstFitStoragePoolAllocator returning 1 sui= table storage pools > 2013-05-03 12:41:54,945 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Trying to find a potenial host and associated storage pools fr= om the suitable host/pool lists for this VM > 2013-05-03 12:41:54,945 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Checking if host: 5 can access any suitable storage pool for v= olume: ROOT > 2013-05-03 12:41:54,947 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Host: 5 can access pool: 200 > 2013-05-03 12:41:54,947 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Found a potential host id: 5 name: cs-kvm014 and associated st= orage pools for this VM > 2013-05-03 12:41:54,950 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluste= r(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cl= uster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))] > 2013-05-03 12:41:54,985 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) VM state transitted from :Stopped to Starting with event= : StartRequestedvm's original host id: null new host id: null host id befor= e state transition: null > 2013-05-03 12:41:54,985 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Successfully transitioned to start state for VM[User|MY-= VM] reservation id =3D 32088e11-31ca-49f2-a4f4-ccaed76ad0a8 > 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Trying to deploy VM, vm has dcId: 1 and podId: null > 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) advanceStart: DeploymentPlan is provided, using dcId:1, = podId: 1, clusterId: 1, hostId: 5, poolId: null > 2013-05-03 12:41:55,000 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Deploy avoids pods: null, clusters: null, hosts: null > 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) DeploymentPlanner allocation algorithm: userconcentratedpod_ra= ndom > 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Trying to allocate a host and storage pools from dc:1, pod:1,c= luster:1, requested cpu: 1000, requested ram: 1073741824 > 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Is ROOT volume READY (pool already allocated)?: No > 2013-05-03 12:41:55,004 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) DeploymentPlan has host_id specified, making no checks on this= host, looks like admin test: 5 > 2013-05-03 12:41:55,006 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Looking for suitable pools for this host under zone: 1, pod: 1= , cluster: 1 > 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Checking suitable pools for volume (Id, Type): (20,ROOT) > 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) We need to allocate new storagepool for this volume > 2013-05-03 12:41:55,009 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Calling StoragePoolAllocators to find suitable pools > 2013-05-03 12:41:55,009 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) Looking for pools in dc: 1 pod:1 cluster:1 > 2013-05-03 12:41:55,011 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) FirstFitStoragePoolAllocator has 1 pools to = check for allocation > 2013-05-03 12:41:55,012 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Checking if storage pool is suitable, name: = PRIMARY ,poolId: 200 > 2013-05-03 12:41:55,012 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Is localStorageAllocationNeeded? false > 2013-05-03 12:41:55,012 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-24:job-33) Is storage pool shared? true > 2013-05-03 12:41:55,016 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-24:job-33) Checking pool 200 for storage, totalSize: 7999230836736, u= sedBytes: 452555964416, usedPct: 0.056574934972205476, disable threshold: 0= .85 > 2013-05-03 12:41:55,027 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-24:job-33) Checking pool: 200 for volume allocation [Vol[20|vm=3D17|R= OOT]], maxSize : 15998461673472, totalAllocatedSize : 266014556160, askingS= ize : 42949672960, allocated disable threshold: 0.85 > 2013-05-03 12:41:55,027 DEBUG [storage.allocator.FirstFitStoragePoolAlloc= ator] (Job-Executor-24:job-33) FirstFitStoragePoolAllocator returning 1 sui= table storage pools > 2013-05-03 12:41:55,027 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Trying to find a potenial host and associated storage pools fr= om the suitable host/pool lists for this VM > 2013-05-03 12:41:55,027 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Checking if host: 5 can access any suitable storage pool for v= olume: ROOT > 2013-05-03 12:41:55,029 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Host: 5 can access pool: 200 > 2013-05-03 12:41:55,029 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Found a potential host id: 5 name: cs-kvm014 and associated st= orage pools for this VM > 2013-05-03 12:41:55,031 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluste= r(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cl= uster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))] > 2013-05-03 12:41:55,031 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Deployment found - P0=3DVM[User|MY-VM], P0=3DDest[Zone(= Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest= [Zone(1)-Pod(1)-Cluster(1)-Host(5)-Storage(Volume(20|ROOT-->Pool(200))] > 2013-05-03 12:41:55,054 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) VM state transitted from :Starting to Starting with even= t: OperationRetryvm's original host id: null new host id: 5 host id before = state transition: null > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) Hosts's actual total CPU: 20216 and CPU after applying o= verprovisioning: 202160 > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) We are allocating VM, increasing the used capacity of th= is host:5 > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) Current Used CPU: 4500 , Free CPU:197660 ,Requested CPU:= 1000 > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) Current Used RAM: 2952790016 , Free RAM:13760352256 ,Req= uested RAM: 1073741824 > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) CPU STATS after allocation: for host: 5, old used: 4500,= old reserved: 0, actual total: 20216, total with overprovisioning: 202160;= new used:5500, reserved:0; requested cpu:1000,alloc_from_last:false > 2013-05-03 12:41:55,067 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) RAM STATS after allocation: for host: 5, old used: 29527= 90016, old reserved: 0, total: 16713142272; new used: 4026531840, reserved:= 0; requested mem: 1073741824,alloc_from_last:false > 2013-05-03 12:41:55,081 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) VM is being created in podId: 1 > 2013-05-03 12:41:55,086 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Lock is acquired for network id 203 as a part of network i= mplement > 2013-05-03 12:41:55,086 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Network id=3D203 is already implemented > 2013-05-03 12:41:55,087 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Lock is released for network id 203 as a part of network i= mplement > 2013-05-03 12:41:55,113 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Changing active number of nics for network id=3D203 on 1 > 2013-05-03 12:41:55,126 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Asking VirtualRouter to prepare for Nic[22-17-null-null] > 2013-05-03 12:41:55,144 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-24:job-33) Lock is acquired for network id 203 as a = part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storag= e(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Stor= age(Volume(20|ROOT-->Pool(200))] > 2013-05-03 12:41:55,150 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-24:job-33) Lock is released for network id 203 as a = part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storag= e(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(5)-Stor= age(Volume(20|ROOT-->Pool(200))] > 2013-05-03 12:41:55,175 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (Job-Executor-24:job-33) Applying dhcp entry in network Ntwk[203|G= uest|5] > 2013-05-03 12:41:55,204 DEBUG [agent.transport.Request] (Job-Executor-24:= job-33) Seq 2-1920335888: Sending { Cmd , MgmtId: 90520747364525, via: 2, = Ver: v1, Flags: 100111, [{"routing.DhcpEntryCommand":{"vmName":"MY-VM","def= aultDns":"10.11.110.229","duid":"00:03:00:01:null","isDefault":true,"access= Details":{"router.guest.ip":"10.11.110.229","zone.network.type":"Advanced",= "router.name":"r-4-VM","router.ip":"169.254.0.207"},"wait":0}}] } > 2013-05-03 12:41:55,212 DEBUG [agent.transport.Request] (AgentManager-Han= dler-2:null) Seq 2-1920335888: Processing: { Ans: , MgmtId: 90520747364525= , via: 2, Ver: v1, Flags: 110, [{"Answer":{"result":false,"details":"java.l= ang.NullPointerException\n\tat java.lang.ProcessBuilder.start(ProcessBuilde= r.java:457)\n\tat com.cloud.utils.script.Script.execute(Script.java:183)\n\= tat com.cloud.utils.script.Script.execute(Script.java:161)\n\tat com.cloud.= agent.resource.virtualnetwork.VirtualRoutingResource.execute(VirtualRouting= Resource.java:608)\n\tat com.cloud.agent.resource.virtualnetwork.VirtualRou= tingResource.executeRequest(VirtualRoutingResource.java:139)\n\tat com.clou= d.hypervisor.kvm.resource.LibvirtComputingResource.executeRequest(LibvirtCo= mputingResource.java:1118)\n\tat com.cloud.agent.Agent.processRequest(Agent= .java:525)\n\tat com.cloud.agent.Agent$AgentRequestHandler.doTask(Agent.jav= a:852)\n\tat com.cloud.utils.nio.Task.run(Task.java:83)\n\tat java.util.con= current.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)\n\tat ja= va.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:61= 5)\n\tat java.lang.Thread.run(Thread.java:679)\n","wait":0}}] } > 2013-05-03 12:41:55,212 DEBUG [agent.manager.AgentAttache] (AgentManager-= Handler-2:null) Seq 2-1920335888: No more commands found > 2013-05-03 12:41:55,212 DEBUG [agent.transport.Request] (Job-Executor-24:= job-33) Seq 2-1920335888: Received: { Ans: , MgmtId: 90520747364525, via: = 2, Ver: v1, Flags: 110, { Answer } } > 2013-05-03 12:41:55,212 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Unable to contact resource. > com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1]= is unreachable: Unable to apply dhcp entry on router > at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.ap= plyRules(VirtualNetworkApplianceManagerImpl.java:3431) > at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.ap= plyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:2664) > at com.cloud.network.element.VirtualRouterElement.addDhcpEntry(Vi= rtualRouterElement.java:831) > at com.cloud.network.NetworkManagerImpl.prepareElement(NetworkMan= agerImpl.java:1547) > at com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManager= Impl.java:1658) > at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImp= l.java:1599) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMac= hineManagerImpl.java:746) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:471) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:212) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3865) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3458) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3444) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(= DeployVMCmd.java:379) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:437) > 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(ThreadPoolEx= ecutor.java:1146) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:615) > at java.lang.Thread.run(Thread.java:679) > 2013-05-03 12:41:55,228 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Cleaning up resources for the vm VM[User|MY-VM] in Start= ing state > 2013-05-03 12:41:55,231 DEBUG [agent.transport.Request] (Job-Executor-24:= job-33) Seq 5-2052983787: Sending { Cmd , MgmtId: 90520747364525, via: 5, = Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-17-V= M","wait":0}}] } > 2013-05-03 12:41:55,386 DEBUG [agent.transport.Request] (AgentManager-Han= dler-14:null) Seq 5-2052983787: Processing: { Ans: , MgmtId: 9052074736452= 5, via: 5, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"= wait":0}}] } > 2013-05-03 12:41:55,387 DEBUG [agent.manager.AgentAttache] (AgentManager-= Handler-14:null) Seq 5-2052983787: No more commands found > 2013-05-03 12:41:55,387 DEBUG [agent.transport.Request] (Job-Executor-24:= job-33) Seq 5-2052983787: Received: { Ans: , MgmtId: 90520747364525, via: = 5, Ver: v1, Flags: 110, { StopAnswer } } > 2013-05-03 12:41:55,393 DEBUG [cloud.network.NetworkManagerImpl] (Job-Exe= cutor-24:job-33) Changing active number of nics for network id=3D203 on -1 > 2013-05-03 12:41:55,406 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Successfully released network resources for the vm VM[Us= er|MY-VM] > 2013-05-03 12:41:55,406 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-E= xecutor-24:job-33) Successfully cleanued up resources for the vm VM[User|MY= -VM] in Starting state > 2013-05-03 12:41:55,409 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executo= r-24:job-33) DataCenter id =3D '1' provided is in avoid set, DeploymentPlan= ner cannot allocate the VM, returning. > 2013-05-03 12:41:55,438 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) VM state transitted from :Starting to Stopped with event= : OperationFailedvm's original host id: null new host id: null host id befo= re state transition: 5 > 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) Hosts's actual total CPU: 20216 and CPU after applying o= verprovisioning: 202160 > 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) release cpu from host: 5, old used: 5500,reserved: 0, ac= tual total: 20216, total with overprovisioning: 202160; new used: 4500,rese= rved:0; movedfromreserved: false,moveToReserveredfalse > 2013-05-03 12:41:55,445 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) release mem from host: 5, old used: 4026531840,reserved:= 0, total: 16713142272; new used: 2952790016,reserved:0; movedfromreserved:= false,moveToReserveredfalse > 2013-05-03 12:41:55,462 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-= 24:job-33) Destroying vm VM[User|MY-VM] as it failed to create on Host with= Id:null > 2013-05-03 12:41:55,492 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-E= xecutor-24:job-33) VM state transitted from :Stopped to Error with event: O= perationFailedToErrorvm's original host id: null new host id: null host id = before state transition: null > 2013-05-03 12:41:55,618 INFO [user.vm.DeployVMCmd] (Job-Executor-24:job-= 33) com.cloud.exception.InsufficientServerCapacityException: Unable to crea= te a deployment for VM[User|MY-VM]Scope=3Dinterface com.cloud.dc.DataCenter= ; id=3D1 > 2013-05-03 12:41:55,618 INFO [user.vm.DeployVMCmd] (Job-Executor-24:job-= 33) Unable to create a deployment for VM[User|MY-VM] > com.cloud.exception.InsufficientServerCapacityException: Unable to create= a deployment for VM[User|MY-VM]Scope=3Dinterface com.cloud.dc.DataCenter; = id=3D1 > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMac= hineManagerImpl.java:728) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineMan= agerImpl.java:471) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerI= mpl.deployVirtualMachine(VMEntityManagerImpl.java:212) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEn= tityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3865) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3458) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManag= erImpl.java:3444) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(= DeployVMCmd.java:379) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:162) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.= java:437) > 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(ThreadPoolEx= ecutor.java:1146) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolE= xecutor.java:615) > at java.lang.Thread.run(Thread.java:679) > 2013-05-03 12:41:55,619 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-24:job-33) Complete async job-33, jobStatus: 2, resultCode: 530, resul= t: Error Code: 533 Error text: Unable to create a deployment for VM[User|MY= -VM] > 2013-05-03 12:41:55,782 DEBUG [cloud.server.StatsCollector] (StatsCollect= or-3:null) HostStatsCollector is running... > 2013-05-03 12:41:56,375 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 2-1920335889: Received: { Ans: , MgmtId: 90520747364525, via: 2= , Ver: v1, Flags: 10, { GetHostStatsAnswer } } > 2013-05-03 12:41:56,934 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 5-2052983788: Received: { Ans: , MgmtId: 90520747364525, via: 5= , Ver: v1, Flags: 10, { GetHostStatsAnswer } } > 2013-05-03 12:41:57,799 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DqueryAsyncJobResu= lt&jobId=3Dda527ca7-826a-4d51-9793-3f7100b3c043&response=3Djson&sessionkey= =3DeXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577717824 > 2013-05-03 12:41:57,812 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-16:null) Async job-33 completed > 2013-05-03 12:41:57,817 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DqueryAsyncJobResult= &jobId=3Dda527ca7-826a-4d51-9793-3f7100b3c043&response=3Djson&sessionkey=3D= eXFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577717824 > 2013-05-03 12:41:57,827 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.0.28.16 -- GET command=3DlistVirtualMachin= es&id=3D6dd83da7-9356-4a24-aafb-3a73e3f2cd75&response=3Djson&sessionkey=3De= XFmgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577717852 > 2013-05-03 12:41:57,858 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:nu= ll) =3D=3D=3DEND=3D=3D=3D 10.0.28.16 -- GET command=3DlistVirtualMachines= &id=3D6dd83da7-9356-4a24-aafb-3a73e3f2cd75&response=3Djson&sessionkey=3DeXF= mgvJpWd7KmHo0%2BK%2B%2BaLMM3DI%3D&_=3D1367577717852 > 2013-05-03 12:42:02,518 DEBUG [cloud.cluster.ClusterManagerImpl] (Cluster= -Heartbeat-1:null) Management server heartbeat takes too long to finish. pr= ofiler: Done. Duration: 1942ms, profilerHeartbeatUpdate: Done. Duration: 19= 41ms, profilerPeerScan: Done. Duration: 1ms, profilerAgentLB: Done. Duratio= n: 0ms > 2013-05-03 12:42:09,339 DEBUG [cloud.server.StatsCollector] (StatsCollect= or-3:null) VmStatsCollector is running... > 2013-05-03 12:42:09,382 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl= ] (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet > 2013-05-03 12:42:09,394 DEBUG [agent.transport.Request] (StatsCollector-3= :null) Seq 5-2052983789: Received: { Ans: , MgmtId: 90520747364525, via: 5= , Ver: v1, Flags: 10, { GetVmStatsAnswer } } > 2013-05-03 12:42:10,175 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:42:10,176 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:42:10,193 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:42:10,197 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:42:13,612 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-6:null) Ping from 2 > 2013-05-03 12:42:14,717 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-3:null) Ping from 6 > 2013-05-03 12:42:14,803 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-8:null) Ping from 4 > 2013-05-03 12:42:15,235 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-11:null) Ping from 5 > 2013-05-03 12:42:39,382 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl= ] (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet > 2013-05-03 12:42:40,175 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:42:40,176 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:42:40,193 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status. > 2013-05-03 12:42:40,196 DEBUG [network.router.VirtualNetworkApplianceMana= gerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status= . > 2013-05-03 12:42:41,140 DEBUG [cloud.server.StatsCollector] (StatsCollect= or-2:null) StorageCollector is running... > 2013-05-03 12:42:41,201 DEBUG [agent.transport.Request] (StatsCollector-2= :null) Seq 6-685442216: Received: { Ans: , MgmtId: 90520747364525, via: 6,= Ver: v1, Flags: 10, { GetStorageStatsAnswer } } > 2013-05-03 12:42:41,283 DEBUG [agent.transport.Request] (StatsCollector-2= :null) Seq 2-1920335890: Received: { Ans: , MgmtId: 90520747364525, via: 2= , Ver: v1, Flags: 10, { GetStorageStatsAnswer } } > Cheers, > Shashi -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira