Thank you Adriano, that's right! I skipped it.
Regards, José -----Mensaje original----- De: Adriano Paterlini [mailto:[email protected]] Enviado el: miércoles, 18 de febrero de 2015 15:18 Para: [email protected] Asunto: Re: Error when changing Service offering José, check your service offering, maximum cpu speed request for your host 1 is 1999, instead of rounded 2000. from your log: Host: 1 doesn't have cpu capability (cpu:32, speed:1999) to support requested CPU: 4 and requested speed: 2000 On Wed, Feb 18, 2015 at 4:45 PM, José Egas López <[email protected]> wrote: > Hi all, when I want to change the service offering for one VM, the change > is successful, but when I try to power on the VM and I get the error "Job > failed due to exception Unable to create a deployment for > VM[User|i-2-28-VM]", on the log is: > ******************************************** > > > 2015-02-18 11:53:54,255 DEBUG [c.c.a.ApiServlet] > (catalina-exec-12:ctx-98804190 ctx-10da719e) ===END=== 172.30.1.107 -- > GET > command=listZones&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278549720 > 2015-02-18 11:53:54,261 DEBUG [c.c.a.ApiServlet] > (catalina-exec-15:ctx-47da5ba4) ===START=== 172.30.1.107 -- GET > command=listAlerts&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&page=1&pageSize=4&_=1424278549800 > 2015-02-18 11:53:54,289 DEBUG [c.c.a.ApiServlet] > (catalina-exec-15:ctx-47da5ba4 ctx-e7805e14) ===END=== 172.30.1.107 -- > GET > command=listAlerts&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&page=1&pageSize=4&_=1424278549800 > 2015-02-18 11:53:54,296 DEBUG [c.c.a.ApiServlet] > (catalina-exec-16:ctx-c03ace9f) ===START=== 172.30.1.107 -- GET > command=listHosts&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&state=Alert&page=1&pageSize=4&_=1424278549835 > 2015-02-18 11:53:54,309 DEBUG [c.c.a.q.QueryManagerImpl] > (catalina-exec-16:ctx-c03ace9f ctx-ccde2946) >>>Searching for hosts>>> > 2015-02-18 11:53:54,324 DEBUG [c.c.a.q.QueryManagerImpl] > (catalina-exec-16:ctx-c03ace9f ctx-ccde2946) >>>Generating Response>>> > 2015-02-18 11:53:54,325 DEBUG [c.c.a.ApiServlet] > (catalina-exec-16:ctx-c03ace9f ctx-ccde2946) ===END=== 172.30.1.107 -- > GET > command=listHosts&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&state=Alert&page=1&pageSize=4&_=1424278549835 > 2015-02-18 11:53:54,333 DEBUG [c.c.a.ApiServlet] > (catalina-exec-13:ctx-1e771d43) ===START=== 172.30.1.107 -- GET > command=listCapacity&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1424278549871 > 2015-02-18 11:53:54,366 DEBUG [c.c.a.ApiServlet] > (catalina-exec-13:ctx-1e771d43 ctx-5220b767) ===END=== 172.30.1.107 -- > GET > command=listCapacity&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&fetchLatest=false&sortBy=usage&page=0&pagesize=8&_=1424278549871 > 2015-02-18 11:53:56,727 DEBUG [c.c.s.StatsCollector] > (StatsCollector-4:ctx-468d7732) AutoScaling Monitor is running... > 2015-02-18 11:53:56,856 DEBUG [c.c.s.StatsCollector] > (StatsCollector-1:ctx-5af8f6c6) HostStatsCollector is running... > 2015-02-18 11:53:56,882 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-4:ctx-5678194a) Seq 1-4574812796478291976: Executing request > 2015-02-18 11:53:56,956 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-4:ctx-5678194a) Seq 1-4574812796478291976: Response Received: > 2015-02-18 11:53:56,957 DEBUG [c.c.a.t.Request] > (StatsCollector-1:ctx-5af8f6c6) Seq 1-4574812796478291976: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetHostStatsAnswer } } > 2015-02-18 11:53:57,022 DEBUG [c.c.s.StatsCollector] > (StatsCollector-3:ctx-e4792f58) StorageCollector is running... > 2015-02-18 11:53:57,100 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-e4792f58) Seq 3-9163417866815406090: Received: { > Ans: , MgmtId: 345052570767, via: 3, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:53:57,108 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-5:ctx-6242e3ba) Seq 1-4574812796478291977: Executing request > 2015-02-18 11:53:57,193 DEBUG [c.c.h.v.r.VmwareResource] > (DirectAgent-5:ctx-6242e3ba 192.168.238.51) Datastore summary info, > storageId: 02afcc0e-83af-39d9-ab5e-5baba1b1aa72, localPath: > /FDatacenter/ESXi51Datastore, poolType: VMFS, capacity: 291789340672, free: > 54767124480, used: 237022216192 > 2015-02-18 11:53:57,194 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-5:ctx-6242e3ba) Seq 1-4574812796478291977: Response Received: > 2015-02-18 11:53:57,195 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-e4792f58) Seq 1-4574812796478291977: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:53:57,580 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] > (secstorage-1:ctx-0870c9c5) Zone 1 is ready to launch secondary storage VM > 2015-02-18 11:53:57,649 DEBUG [c.c.s.StatsCollector] > (StatsCollector-2:ctx-7895c606) VmStatsCollector is running... > 2015-02-18 11:53:57,689 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-1:ctx-890470f1) Seq 1-4574812796478291978: Executing request > 2015-02-18 11:53:57,922 DEBUG [c.c.a.ApiServlet] > (catalina-exec-19:ctx-565b6baa) ===START=== 172.30.1.107 -- GET > command=listVirtualMachines&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&listAll=true&page=1&pagesize=20&_=1424278553393 > 2015-02-18 11:53:58,004 DEBUG [c.c.a.ApiServlet] > (catalina-exec-19:ctx-565b6baa ctx-8245be4c) ===END=== 172.30.1.107 -- > GET > command=listVirtualMachines&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&listAll=true&page=1&pagesize=20&_=1424278553393 > 2015-02-18 11:53:58,018 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) find VM i-3-30-VM on host > 2015-02-18 11:53:58,018 INFO [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) VM i-3-30-VM not found in host > cache > 2015-02-18 11:53:58,019 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) load VM cache on host > 2015-02-18 11:53:58,060 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) find VM i-3-31-VM on host > 2015-02-18 11:53:58,060 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) VM i-3-31-VM found in host cache > 2015-02-18 11:53:58,066 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) find VM i-3-32-VM on host > 2015-02-18 11:53:58,066 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-1:ctx-890470f1 192.168.238.51) VM i-3-32-VM found in host cache > 2015-02-18 11:53:58,073 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-1:ctx-890470f1) Seq 1-4574812796478291978: Response Received: > 2015-02-18 11:53:58,073 DEBUG [c.c.a.t.Request] > (StatsCollector-2:ctx-7895c606) Seq 1-4574812796478291978: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer > } } > 2015-02-18 11:53:58,305 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-b98c6718) Zone 1 is ready to launch console proxy > 2015-02-18 11:53:58,864 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-10:null) SeqA 2-90488: Processing Seq 2-90488: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:53:58,874 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-10:null) SeqA 2-90488: Sending Seq 2-90488: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:54:05,625 WARN [c.c.a.m.DirectAgentAttache] > (DirectAgentCronJob-2:ctx-8e601903) Unable to get current status on > 1(192.168.238.51) > 2015-02-18 11:54:08,865 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-11:null) SeqA 2-90489: Processing Seq 2-90489: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:54:08,872 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-11:null) SeqA 2-90489: Sending Seq 2-90489: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:54:11,739 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-d5228702) Found 0 routers to update status. > 2015-02-18 11:54:11,741 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-d5228702) Found 0 networks to update RvR status. > 2015-02-18 11:54:41,987 DEBUG [c.c.a.ApiServlet] > (catalina-exec-22:ctx-00632ceb ctx-fbec329b) ===END=== 172.30.1.107 -- > GET > command=listOsTypes&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278597006 > 2015-02-18 11:54:44,649 DEBUG [c.c.a.ApiServlet] > (catalina-exec-2:ctx-a580a4d0) ===START=== 172.30.1.107 -- GET > command=startVirtualMachine&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278600139 > 2015-02-18 11:54:44,726 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (catalina-exec-2:ctx-a580a4d0 ctx-d5f0a8e0) submit async job-314, details: > AsyncJobVO {id:314, userId: 2, accountId: 2, instanceType: VirtualMachine, > instanceId: 28, cmd: > org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: > {"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","response":"json","sessionkey":"o3TXqjMhbsF68S+tnSDYwhsotXo\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1424278600139","uuid":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","ctxAccountId":"2","ctxStartEventId":"637"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2015-02-18 11:54:44,727 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Add job-314 into job monitoring > 2015-02-18 11:54:44,728 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Executing AsyncJobVO {id:314, > userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 28, cmd: > org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin, cmdInfo: > {"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","response":"json","sessionkey":"o3TXqjMhbsF68S+tnSDYwhsotXo\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4\"}","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1424278600139","uuid":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","ctxAccountId":"2","ctxStartEventId":"637"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2015-02-18 11:54:44,729 DEBUG [c.c.a.ApiServlet] > (catalina-exec-2:ctx-a580a4d0 ctx-d5f0a8e0) ===END=== 172.30.1.107 -- GET > command=startVirtualMachine&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278600139 > 2015-02-18 11:54:44,900 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Deploy avoids pods: > [], clusters: [], hosts: [] > 2015-02-18 11:54:44,903 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) DeploymentPlanner > allocation algorithm: com.cloud.deploy.FirstFitPlanner@21a1bc35 > 2015-02-18 11:54:44,903 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Trying to allocate a > host and storage pools from dc:1, pod:null,cluster:null, requested cpu: > 8000, requested ram: 6442450944 > 2015-02-18 11:54:44,903 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Is ROOT volume READY > (pool already allocated)?: Yes > 2015-02-18 11:54:44,904 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) This VM has last > host_id specified, trying to choose the same host: 1 > 2015-02-18 11:54:44,921 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Checking if host: 1 > has enough capacity for requested CPU: 8000 and requested RAM: 6442450944 , > cpuOverprovisioningFactor: 1.0 > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Hosts's actual total > CPU: 63968 and CPU after applying overprovisioning: 63968 > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) We need to allocate > to the last host again, so checking if there is enough reserved capacity > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Reserved CPU: 6000 , > Requested CPU: 8000 > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Reserved RAM: > 4294967296 , Requested RAM: 6442450944 > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) STATS: Failed to > alloc resource from host: 1 reservedCpu: 6000, requested cpu: 8000, > reservedMem: 4294967296, requested mem: 6442450944 > 2015-02-18 11:54:44,926 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Host does not have > enough reserved CPU available, cannot allocate to this host. > 2015-02-18 11:54:44,926 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) The last host of > this VM does not have enough capacity > 2015-02-18 11:54:44,926 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Cannot choose the > last host to deploy this VM > 2015-02-18 11:54:44,927 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Searching all > possible resources under this Zone: 1 > 2015-02-18 11:54:44,929 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Listing clusters in > order of aggregate capacity, that have (atleast one host with) enough CPU > and RAM capacity under this Zone: 1 > 2015-02-18 11:54:44,936 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Removing from the > clusterId list these clusters from avoid set: [] > 2015-02-18 11:54:44,950 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Checking resources > in Cluster: 1 under Pod: 1 > 2015-02-18 11:54:44,954 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 > 2015-02-18 11:54:44,961 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for > allocation: [Host[-1-Routing]] > 2015-02-18 11:54:44,971 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Found 1 hosts for allocation after > prioritization: [Host[-1-Routing]] > 2015-02-18 11:54:44,971 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Looking for speed=8000Mhz, Ram=6144 > 2015-02-18 11:54:44,986 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Host: 1 doesn't have cpu capability (cpu:32, > speed:1999) to support requested CPU: 4 and requested speed: 2000 > 2015-02-18 11:54:44,986 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for > requested CPU: 8000 and requested RAM: 6442450944 , > cpuOverprovisioningFactor: 1.0 > 2015-02-18 11:54:44,991 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Hosts's actual total CPU: 63968 and CPU after > applying overprovisioning: 63968 > 2015-02-18 11:54:44,992 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Free CPU: 41468 , Requested CPU: 8000 > 2015-02-18 11:54:44,992 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Free RAM: 51905892352 , Requested RAM: 6442450944 > 2015-02-18 11:54:44,992 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Host has enough CPU and RAM available > 2015-02-18 11:54:44,992 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 16500, > reserved: 6000, actual total: 63968, total with overprovisioning: 63968; > requested cpu:8000,alloc_from_last_host?:false ,considerReservedCapacity?: > true > 2015-02-18 11:54:44,992 DEBUG [c.c.c.CapacityManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: > 12482248704, reserved: 4294967296, total: 68683108352; requested mem: > 6442450944,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2015-02-18 11:54:44,992 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Not using host 1; host has cpu capability? false, > host has capacity?true > 2015-02-18 11:54:44,992 DEBUG [c.c.a.m.a.i.FirstFitAllocator] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c > FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts > 2015-02-18 11:54:44,992 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) No suitable hosts > found > 2015-02-18 11:54:44,992 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) No suitable hosts > found under this Cluster: 1 > 2015-02-18 11:54:44,996 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Could not find > suitable Deployment Destination for this VM under any clusters, returning. > 2015-02-18 11:54:44,996 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Searching all > possible resources under this Zone: 1 > 2015-02-18 11:54:44,998 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Listing clusters in > order of aggregate capacity, that have (atleast one host with) enough CPU > and RAM capacity under this Zone: 1 > 2015-02-18 11:54:45,005 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Removing from the > clusterId list these clusters from avoid set: [1] > 2015-02-18 11:54:45,007 DEBUG [c.c.d.FirstFitPlanner] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) No clusters found > after removing disabled clusters and clusters in avoid list, returning. > 2015-02-18 11:54:45,027 DEBUG [o.a.c.f.j.i.JobSerializerHelper] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Job GSON Builder > initialized. > 2015-02-18 11:54:45,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Sync job-315 > execution on object VmWorkJobQueue.28 > 2015-02-18 11:54:45,060 WARN [c.c.u.d.Merovingian2] > (API-Job-Executor-2:ctx-8d6562c2 job-314 ctx-2a163f4c) Was unable to find > lock for the key vm_instance28 and thread id 38728715 > 2015-02-18 11:54:45,993 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Searching > all possible resources under this Zone: 1 > 2015-02-18 11:54:45,995 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Listing > clusters in order of aggregate capacity, that have (atleast one host with) > enough CPU and RAM capacity under this Zone: 1 > 2015-02-18 11:54:46,002 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Removing > from the clusterId list these clusters from avoid set: [1] > 2015-02-18 11:54:46,004 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) No clusters > found after removing disabled clusters and clusters in avoid list, > returning. > 2015-02-18 11:54:46,022 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Deploy > avoids pods: [], clusters: [1], hosts: [1] > 2015-02-18 11:54:46,024 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) > DeploymentPlanner allocation algorithm: > com.cloud.deploy.FirstFitPlanner@21a1bc35 > 2015-02-18 11:54:46,024 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Trying to > allocate a host and storage pools from dc:1, pod:1,cluster:null, requested > cpu: 8000, requested ram: 6442450944 > 2015-02-18 11:54:46,024 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Is ROOT > volume READY (pool already allocated)?: No > 2015-02-18 11:54:46,024 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) This VM has > last host_id specified, trying to choose the same host: 1 > 2015-02-18 11:54:46,027 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) The last > host of this VM is in avoid set > 2015-02-18 11:54:46,028 DEBUG [c.c.d.DeploymentPlanningManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Cannot > choose the last host to deploy this VM > 2015-02-18 11:54:46,028 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Searching > resources only under specified Pod: 1 > 2015-02-18 11:54:46,028 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Listing > clusters in order of aggregate capacity, that have (atleast one host with) > enough CPU and RAM capacity under this Pod: 1 > 2015-02-18 11:54:46,034 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Removing > from the clusterId list these clusters from avoid set: [1] > 2015-02-18 11:54:46,036 DEBUG [c.c.d.FirstFitPlanner] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) No clusters > found after removing disabled clusters and clusters in avoid list, > returning. > 2015-02-18 11:54:46,063 DEBUG [c.c.c.CapacityManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) VM state > transitted from :Starting to Stopped with event: OperationFailedvm's > original host id: 1 new host id: null host id before state transition: null > 2015-02-18 11:54:46,079 ERROR [c.c.v.VmWorkJobHandlerProxy] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Invocation > exception, caused by: > com.cloud.exception.InsufficientServerCapacityException: Unable to create a > deployment for VM[User|i-2-28-VM]Scope=interface com.cloud.dc.DataCenter; > id=1 > 2015-02-18 11:54:46,079 INFO [c.c.v.VmWorkJobHandlerProxy] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315 ctx-e646a0b8) Rethrow > exception com.cloud.exception.InsufficientServerCapacityException: Unable > to create a deployment for VM[User|i-2-28-VM]Scope=interface > com.cloud.dc.DataCenter; id=1 > 2015-02-18 11:54:46,080 DEBUG [c.c.v.VmWorkJobDispatcher] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Done with run of VM work > job: com.cloud.vm.VmWorkStart for VM 28, job origin: 314 > 2015-02-18 11:54:46,080 ERROR [c.c.v.VmWorkJobDispatcher] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Unable to complete > AsyncJobVO {id:315, userId: 2, accountId: 2, instanceType: null, > instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: > rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAHHQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: Wed Feb 18 11:54:45 ECT 2015}, job > origin:314 > com.cloud.exception.InsufficientServerCapacityException: Unable to create > a deployment for VM[User|i-2-28-VM]Scope=interface com.cloud.dc.DataCenter; > id=1 > at > com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947) > at > com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195) > 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:606) > at > com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107) > at > com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340) > 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.run(FutureTask.java:262) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > 2015-02-18 11:54:46,086 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Complete async job-315, > jobStatus: FAILED, resultCode: 0, result: > rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItMjgtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4 > 2015-02-18 11:54:46,102 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Done executing > com.cloud.vm.VmWorkStart for job-315 > 2015-02-18 11:54:46,128 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Sync queue (111) is > currently empty > 2015-02-18 11:54:46,129 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (Work-Job-Executor-1:ctx-3cda7ea0 job-314/job-315) Remove job-315 from job > monitoring > 2015-02-18 11:54:46,136 ERROR [c.c.a.ApiAsyncJobDispatcher] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Unexpected exception while > executing org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin > java.lang.RuntimeException: Job failed due to exception Unable to create a > deployment for VM[User|i-2-28-VM] > at > com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114) > 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.run(FutureTask.java:262) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:745) > 2015-02-18 11:54:46,139 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Complete async job-314, > jobStatus: FAILED, resultCode: 530, result: > org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Job > failed due to exception Unable to create a deployment for > VM[User|i-2-28-VM]"} > 2015-02-18 11:54:46,149 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Done executing > org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-314 > 2015-02-18 11:54:46,156 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-2:ctx-8d6562c2 job-314) Remove job-314 from job monitoring > 2015-02-18 11:54:46,768 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] > (Vm-Operations-Cleanup-1:ctx-b7c0fe65) Expunge completed work job-315 > 2015-02-18 11:54:46,906 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Resetting hosts suitable for reconnect > 2015-02-18 11:54:46,909 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Completed resetting hosts suitable for reconnect > 2015-02-18 11:54:46,910 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Acquiring hosts for clusters already owned by this > management server > 2015-02-18 11:54:46,912 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Completed acquiring hosts for clusters already owned by > this management server > 2015-02-18 11:54:46,912 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Acquiring hosts for clusters not owned by any > management server > 2015-02-18 11:54:46,913 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager > Timer:ctx-36419c71) Completed acquiring hosts for clusters not owned by any > management server > 2015-02-18 11:54:48,878 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-3:null) SeqA 2-90495: Sending Seq 2-90495: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:54:52,656 DEBUG [c.c.a.ApiServlet] > (catalina-exec-6:ctx-f538e8a1) ===START=== 172.30.1.107 -- GET > command=listServiceOfferings&VirtualMachineId=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278608183 > 2015-02-18 11:54:52,722 DEBUG [c.c.a.ApiServlet] > (catalina-exec-6:ctx-f538e8a1 ctx-c3cba7e8) ===END=== 172.30.1.107 -- GET > command=listServiceOfferings&VirtualMachineId=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278608183 > 2015-02-18 11:54:56,731 DEBUG [c.c.s.StatsCollector] > (StatsCollector-4:ctx-6f3ea0d2) AutoScaling Monitor is running... > 2015-02-18 11:54:56,960 DEBUG [c.c.s.StatsCollector] > (StatsCollector-1:ctx-7c576f5e) HostStatsCollector is running... > 2015-02-18 11:54:56,976 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-6:ctx-b839b8d3) Seq 1-4574812796478291979: Executing request > 2015-02-18 11:54:57,074 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-6:ctx-b839b8d3) Seq 1-4574812796478291979: Response Received: > 2015-02-18 11:54:57,075 DEBUG [c.c.a.t.Request] > (StatsCollector-1:ctx-7c576f5e) Seq 1-4574812796478291979: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetHostStatsAnswer } } > 2015-02-18 11:54:57,196 DEBUG [c.c.s.StatsCollector] > (StatsCollector-3:ctx-ec345a4a) StorageCollector is running... > 2015-02-18 11:54:57,269 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-ec345a4a) Seq 3-9163417866815406091: Received: { > Ans: , MgmtId: 345052570767, via: 3, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:54:57,274 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-2:ctx-eac50f42) Seq 1-4574812796478291980: Executing request > 2015-02-18 11:54:57,359 DEBUG [c.c.h.v.r.VmwareResource] > (DirectAgent-2:ctx-eac50f42 192.168.238.51) Datastore summary info, > storageId: 02afcc0e-83af-39d9-ab5e-5baba1b1aa72, localPath: > /FDatacenter/ESXi51Datastore, poolType: VMFS, capacity: 291789340672, free: > 54767124480, used: 237022216192 > 2015-02-18 11:54:57,360 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-2:ctx-eac50f42) Seq 1-4574812796478291980: Response Received: > 2015-02-18 11:54:57,360 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-ec345a4a) Seq 1-4574812796478291980: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:54:57,577 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] > (secstorage-1:ctx-7a0b1a82) Zone 1 is ready to launch secondary storage VM > 2015-02-18 11:54:58,074 DEBUG [c.c.s.StatsCollector] > (StatsCollector-2:ctx-f87facd4) VmStatsCollector is running... > 2015-02-18 11:54:58,101 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-3:ctx-cd5ddcef) Seq 1-4574812796478291981: Executing request > 2015-02-18 11:54:58,311 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-521a6858) Zone 1 is ready to launch console proxy > 2015-02-18 11:54:58,398 DEBUG [c.c.a.ApiServlet] > (catalina-exec-9:ctx-b007b11c) ===START=== 172.30.1.107 -- GET > command=scaleVirtualMachine&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&serviceofferingid=cff39785-dbed-4f58-a494-d358833f0613&_=1424278613922 > 2015-02-18 11:54:58,449 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) find VM i-3-30-VM on host > 2015-02-18 11:54:58,449 INFO [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) VM i-3-30-VM not found in host > cache > 2015-02-18 11:54:58,449 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) load VM cache on host > 2015-02-18 11:54:58,460 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (catalina-exec-9:ctx-b007b11c ctx-d9cd3bf7) submit async job-316, details: > AsyncJobVO {id:316, userId: 2, accountId: 2, instanceType: None, > instanceId: null, cmd: > org.apache.cloudstack.api.command.admin.vm.ScaleVMCmdByAdmin, cmdInfo: > {"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","response":"json","serviceofferingid":"cff39785-dbed-4f58-a494-d358833f0613","sessionkey":"o3TXqjMhbsF68S+tnSDYwhsotXo\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4\",\"com.cloud.offering.ServiceOffering\":\"cff39785-dbed-4f58-a494-d358833f0613\"}","cmdEventType":"VM.UPGRADE","ctxUserId":"2","httpmethod":"GET","_":"1424278613922","uuid":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","ctxAccountId":"2","ctxStartEventId":"640"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2015-02-18 11:54:58,461 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-3:ctx-a1f0e951 job-316) Add job-316 into job monitoring > 2015-02-18 11:54:48,878 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-3:null) SeqA 2-90495: Sending Seq 2-90495: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:54:52,656 DEBUG [c.c.a.ApiServlet] > (catalina-exec-6:ctx-f538e8a1) ===START=== 172.30.1.107 -- GET > command=listServiceOfferings&VirtualMachineId=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278608183 > 2015-02-18 11:54:52,722 DEBUG [c.c.a.ApiServlet] > (catalina-exec-6:ctx-f538e8a1 ctx-c3cba7e8) ===END=== 172.30.1.107 -- GET > command=listServiceOfferings&VirtualMachineId=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278608183 > 2015-02-18 11:54:56,731 DEBUG [c.c.s.StatsCollector] > (StatsCollector-4:ctx-6f3ea0d2) AutoScaling Monitor is running... > 2015-02-18 11:54:56,960 DEBUG [c.c.s.StatsCollector] > (StatsCollector-1:ctx-7c576f5e) HostStatsCollector is running... > 2015-02-18 11:54:56,976 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-6:ctx-b839b8d3) Seq 1-4574812796478291979: Executing request > 2015-02-18 11:54:57,074 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-6:ctx-b839b8d3) Seq 1-4574812796478291979: Response Received: > 2015-02-18 11:54:57,075 DEBUG [c.c.a.t.Request] > (StatsCollector-1:ctx-7c576f5e) Seq 1-4574812796478291979: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetHostStatsAnswer } } > 2015-02-18 11:54:57,196 DEBUG [c.c.s.StatsCollector] > (StatsCollector-3:ctx-ec345a4a) StorageCollector is running... > 2015-02-18 11:54:57,269 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-ec345a4a) Seq 3-9163417866815406091: Received: { > Ans: , MgmtId: 345052570767, via: 3, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:54:57,274 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-2:ctx-eac50f42) Seq 1-4574812796478291980: Executing request > 2015-02-18 11:54:57,359 DEBUG [c.c.h.v.r.VmwareResource] > (DirectAgent-2:ctx-eac50f42 192.168.238.51) Datastore summary info, > storageId: 02afcc0e-83af-39d9-ab5e-5baba1b1aa72, localPath: > /FDatacenter/ESXi51Datastore, poolType: VMFS, capacity: 291789340672, free: > 54767124480, used: 237022216192 > 2015-02-18 11:54:57,360 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-2:ctx-eac50f42) Seq 1-4574812796478291980: Response Received: > 2015-02-18 11:54:57,360 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-ec345a4a) Seq 1-4574812796478291980: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:54:57,577 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] > (secstorage-1:ctx-7a0b1a82) Zone 1 is ready to launch secondary storage VM > 2015-02-18 11:54:58,074 DEBUG [c.c.s.StatsCollector] > (StatsCollector-2:ctx-f87facd4) VmStatsCollector is running... > 2015-02-18 11:54:58,101 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-3:ctx-cd5ddcef) Seq 1-4574812796478291981: Executing request > 2015-02-18 11:54:58,311 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-521a6858) Zone 1 is ready to launch console proxy > 2015-02-18 11:54:58,398 DEBUG [c.c.a.ApiServlet] > (catalina-exec-9:ctx-b007b11c) ===START=== 172.30.1.107 -- GET > command=scaleVirtualMachine&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&serviceofferingid=cff39785-dbed-4f58-a494-d358833f0613&_=1424278613922 > 2015-02-18 11:54:58,449 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) find VM i-3-30-VM on host > 2015-02-18 11:54:58,449 INFO [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) VM i-3-30-VM not found in host > cache > 2015-02-18 11:54:58,449 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) load VM cache on host > 2015-02-18 11:54:58,460 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (catalina-exec-9:ctx-b007b11c ctx-d9cd3bf7) submit async job-316, details: > AsyncJobVO {id:316, userId: 2, accountId: 2, instanceType: None, > instanceId: null, cmd: > org.apache.cloudstack.api.command.admin.vm.ScaleVMCmdByAdmin, cmdInfo: > {"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","response":"json","serviceofferingid":"cff39785-dbed-4f58-a494-d358833f0613","sessionkey":"o3TXqjMhbsF68S+tnSDYwhsotXo\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4\",\"com.cloud.offering.ServiceOffering\":\"cff39785-dbed-4f58-a494-d358833f0613\"}","cmdEventType":"VM.UPGRADE","ctxUserId":"2","httpmethod":"GET","_":"1424278613922","uuid":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","ctxAccountId":"2","ctxStartEventId":"640"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2015-02-18 11:54:58,461 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-3:ctx-a1f0e951 job-316) Add job-316 into job monitoring > 2015-02-18 11:54:58,462 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-3:ctx-a1f0e951 job-316) Executing AsyncJobVO {id:316, > userId: 2, accountId: 2, instanceType: None, instanceId: null, cmd: > org.apache.cloudstack.api.command.admin.vm.ScaleVMCmdByAdmin, cmdInfo: > {"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","response":"json","serviceofferingid":"cff39785-dbed-4f58-a494-d358833f0613","sessionkey":"o3TXqjMhbsF68S+tnSDYwhsotXo\u003d","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4\",\"com.cloud.offering.ServiceOffering\":\"cff39785-dbed-4f58-a494-d358833f0613\"}","cmdEventType":"VM.UPGRADE","ctxUserId":"2","httpmethod":"GET","_":"1424278613922","uuid":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","ctxAccountId":"2","ctxStartEventId":"640"}, > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, > result: null, initMsid: 345052570767, completeMsid: null, lastUpdated: > null, lastPolled: null, created: null} > 2015-02-18 11:54:58,463 DEBUG [c.c.a.ApiServlet] > (catalina-exec-9:ctx-b007b11c ctx-d9cd3bf7) ===END=== 172.30.1.107 -- GET > command=scaleVirtualMachine&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&serviceofferingid=cff39785-dbed-4f58-a494-d358833f0613&_=1424278613922 > 2015-02-18 11:54:58,494 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) find VM i-3-31-VM on host > 2015-02-18 11:54:58,494 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) VM i-3-31-VM found in host cache > 2015-02-18 11:54:58,501 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) find VM i-3-32-VM on host > 2015-02-18 11:54:58,501 DEBUG [c.c.h.v.m.HostMO] > (DirectAgent-3:ctx-cd5ddcef 192.168.238.51) VM i-3-32-VM found in host cache > 2015-02-18 11:54:58,509 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-3:ctx-cd5ddcef) Seq 1-4574812796478291981: Response Received: > 2015-02-18 11:54:58,509 DEBUG [c.c.a.t.Request] > (StatsCollector-2:ctx-f87facd4) Seq 1-4574812796478291981: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer > } } > 2015-02-18 11:54:58,552 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-3:ctx-a1f0e951 job-316 ctx-d324339a) Complete async > job-316, jobStatus: SUCCEEDED, resultCode: 0, result: > org.apache.cloudstack.api.response.UserVmResponse/virtualmachine/{"id":"df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4","name":"windows2012","displayname":"windows2012","account":"admin","domainid":"83cec07c-a72e-11e4-9916-005056bc648f","domain":"ROOT","created":"2015-02-11T10:53:01-0500","state":"Stopped","haenable":false,"zoneid":"cb6e2a8a-f984-48ae-bd2b-9fc415402bcf","zonename":"pharmazone","templateid":"1179264f-efc6-45fc-8766-02ce2c36f253","templatename":"Windows > Server 2012 R2 ESN","templatedisplaytext":"Windows Server 2012 R2 > ESN","passwordenabled":false,"isoid":"1179264f-efc6-45fc-8766-02ce2c36f253","isoname":"Windows > Server 2012 R2 ESN","isodisplaytext":"Windows Server 2012 R2 > ESN","serviceofferingid":"cff39785-dbed-4f58-a494-d358833f0613","serviceofferingname":"Servidor > Farmacia","diskofferingid":"a3a6df06-a9c3-4d73-a77f-32d9ea45de6b","diskofferingname":"Custom","cpunumber":4,"cpuspeed":1500,"memory":4096,"guestosid":"173d30ce-a7c4-11e4-9916-005056bc648f","rootdeviceid":0,"rootdevicetype":"ROOT","securitygroup":[],"nic":[{"id":"a5fd321f-0a62-43c8-8e0f-ba6e501bdf41","networkid":"e1d21873-147e-4ee1-a8fa-8bde1c397156","networkname":"defaultGuestNetwork","netmask":"255.255.255.0","gateway":"192.168.238.245","ipaddress":"192.168.238.97","broadcasturi":"vlan://untagged","traffictype":"Guest","type":"Shared","isdefault":true,"macaddress":"06:39:6c:00:00:0c"}],"hypervisor":"VMware","instancename":"i-2-28-VM","tags":[],"affinitygroup":[],"displayvm":true,"isdynamicallyscalable":false,"ostypeid":168} > 2015-02-18 11:54:58,563 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] > (API-Job-Executor-3:ctx-a1f0e951 job-316) Done executing > org.apache.cloudstack.api.command.admin.vm.ScaleVMCmdByAdmin for job-316 > 2015-02-18 11:54:58,572 INFO [o.a.c.f.j.i.AsyncJobMonitor] > (API-Job-Executor-3:ctx-a1f0e951 job-316) Remove job-316 from job monitoring > 2015-02-18 11:54:58,871 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-5:null) SeqA 2-90496: Processing Seq 2-90496: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:54:58,878 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-5:null) SeqA 2-90496: Sending Seq 2-90496: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:01,519 DEBUG [c.c.a.ApiServlet] > (catalina-exec-8:ctx-98110079) ===START=== 172.30.1.107 -- GET > command=queryAsyncJobResult&jobId=0faa3756-d846-4f74-803e-64644faea814&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617052 > 2015-02-18 11:55:01,566 DEBUG [c.c.a.ApiServlet] > (catalina-exec-8:ctx-98110079 ctx-d56a8f13) ===END=== 172.30.1.107 -- GET > command=queryAsyncJobResult&jobId=0faa3756-d846-4f74-803e-64644faea814&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617052 > 2015-02-18 11:55:01,673 DEBUG [c.c.a.ApiServlet] > (catalina-exec-11:ctx-e4a0b777) ===START=== 172.30.1.107 -- GET > command=listZones&id=cb6e2a8a-f984-48ae-bd2b-9fc415402bcf&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617189 > 2015-02-18 11:55:01,703 DEBUG [c.c.a.ApiServlet] > (catalina-exec-11:ctx-e4a0b777 ctx-a96cfc20) ===END=== 172.30.1.107 -- > GET > command=listZones&id=cb6e2a8a-f984-48ae-bd2b-9fc415402bcf&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617189 > 2015-02-18 11:55:01,716 DEBUG [c.c.a.ApiServlet] > (catalina-exec-10:ctx-57efb74f) ===START=== 172.30.1.107 -- GET > command=listNetworks&id=e1d21873-147e-4ee1-a8fa-8bde1c397156&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617253 > 2015-02-18 11:55:01,789 DEBUG [c.c.a.ApiServlet] > (catalina-exec-10:ctx-57efb74f ctx-28cdd210) ===END=== 172.30.1.107 -- > GET > command=listNetworks&id=e1d21873-147e-4ee1-a8fa-8bde1c397156&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617253 > 2015-02-18 11:55:01,866 DEBUG [c.c.a.ApiServlet] > (catalina-exec-14:ctx-04f51fd0) ===START=== 172.30.1.107 -- GET > command=listVirtualMachines&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617358 > 2015-02-18 11:55:01,920 DEBUG [c.c.a.ApiServlet] > (catalina-exec-14:ctx-04f51fd0 ctx-7a083088) ===END=== 172.30.1.107 -- > GET > command=listVirtualMachines&id=df7d1d0b-47ac-4800-87c0-99e6e1a1aaa4&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617358 > 2015-02-18 11:55:02,040 DEBUG [c.c.a.ApiServlet] > (catalina-exec-12:ctx-200e9159) ===START=== 172.30.1.107 -- GET > command=listOsTypes&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617477 > 2015-02-18 11:55:02,482 DEBUG [c.c.a.ApiServlet] > (catalina-exec-12:ctx-200e9159 ctx-bc655fea) ===END=== 172.30.1.107 -- > GET > command=listOsTypes&response=json&sessionkey=o3TXqjMhbsF68S%2BtnSDYwhsotXo%3D&_=1424278617477 > 2015-02-18 11:55:05,623 WARN [c.c.a.m.DirectAgentAttache] > (DirectAgentCronJob-3:ctx-76c02acf) Unable to get current status on > 1(192.168.238.51) > 2015-02-18 11:55:08,872 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-6:null) SeqA 2-90497: Processing Seq 2-90497: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:08,879 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-6:null) SeqA 2-90497: Sending Seq 2-90497: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:11,738 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-df2779f9) Found 0 routers to update status. > 2015-02-18 11:55:11,740 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-df2779f9) Found 0 networks to update RvR status. > 2015-02-18 11:55:18,874 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-7:null) SeqA 2-90498: Processing Seq 2-90498: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:18,908 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-7:null) SeqA 2-90498: Sending Seq 2-90498: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:23,875 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-8:null) SeqA 2-90499: Processing Seq 2-90499: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:23,883 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-8:null) SeqA 2-90499: Sending Seq 2-90499: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:27,568 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] > (secstorage-1:ctx-addd732c) Zone 1 is ready to launch secondary storage VM > 2015-02-18 11:55:28,301 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-5d532781) Zone 1 is ready to launch console proxy > 2015-02-18 11:55:33,875 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-9:null) SeqA 2-90500: Processing Seq 2-90500: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:33,883 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-9:null) SeqA 2-90500: Sending Seq 2-90500: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:41,739 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-f96716a7) Found 0 routers to update status. > 2015-02-18 11:55:41,741 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] > (RouterStatusMonitor-1:ctx-f96716a7) Found 0 networks to update RvR status. > 2015-02-18 11:55:41,918 INFO [c.c.a.m.AgentManagerImpl] > (AgentMonitor-1:ctx-2c52ccd6) Found the following agents behind on ping: [1] > 2015-02-18 11:55:41,922 DEBUG [c.c.h.Status] (AgentMonitor-1:ctx-2c52ccd6) > Ping timeout for host 1, do invstigation > 2015-02-18 11:55:41,930 INFO [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) Investigating why host 1 has disconnected > with event PingTimeout > 2015-02-18 11:55:41,930 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) checking if agent (1) is alive > 2015-02-18 11:55:41,940 DEBUG [c.c.a.t.Request] > (AgentTaskPool-2:ctx-ca3744d5) Seq 1-4574812796478291982: Sending { Cmd , > MgmtId: 345052570767, via: 1(192.168.238.51), Ver: v1, Flags: 100011, > [{"com.cloud.agent.api.CheckHealthCommand":{"wait":50}}] } > 2015-02-18 11:55:41,940 DEBUG [c.c.a.t.Request] > (AgentTaskPool-2:ctx-ca3744d5) Seq 1-4574812796478291982: Executing: { Cmd > , MgmtId: 345052570767, via: 1(192.168.238.51), Ver: v1, Flags: 100011, > [{"com.cloud.agent.api.CheckHealthCommand":{"wait":50}}] } > 2015-02-18 11:55:41,941 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-7:ctx-6d568e8a) Seq 1-4574812796478291982: Executing request > 2015-02-18 11:55:41,941 INFO [c.c.h.v.r.VmwareResource] > (DirectAgent-7:ctx-6d568e8a 192.168.238.51) Executing resource > CheckHealthCommand: {"wait":50} > 2015-02-18 11:55:42,062 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-7:ctx-6d568e8a) Seq 1-4574812796478291982: Response Received: > 2015-02-18 11:55:42,062 DEBUG [c.c.a.t.Request] > (DirectAgent-7:ctx-6d568e8a) Seq 1-4574812796478291982: Processing: { Ans: > , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, > [{"com.cloud.agent.api.CheckHealthAnswer":{"result":true,"details":"resource > is alive","wait":0}}] } > 2015-02-18 11:55:42,062 DEBUG [c.c.a.t.Request] > (AgentTaskPool-2:ctx-ca3744d5) Seq 1-4574812796478291982: Received: { Ans: > , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { CheckHealthAnswer } } > 2015-02-18 11:55:42,063 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) Details from executing class > com.cloud.agent.api.CheckHealthCommand: resource is alive > 2015-02-18 11:55:42,063 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) agent (1) responded to checkHeathCommand, > reporting that agent is Up > 2015-02-18 11:55:42,063 INFO [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) The state determined is Up > 2015-02-18 11:55:42,063 INFO [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) Agent is determined to be up and running > 2015-02-18 11:55:42,063 INFO [c.c.a.m.AgentManagerImpl] > (AgentTaskPool-2:ctx-ca3744d5) Agent is determined to be up and running > 2015-02-18 11:55:42,063 DEBUG [c.c.h.Status] > (AgentTaskPool-2:ctx-ca3744d5) Transition:[Resource state = Enabled, Agent > event = Ping, Host id = 1, name = 192.168.238.51] > 2015-02-18 11:55:43,875 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-10:null) SeqA 2-90501: Processing Seq 2-90501: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:43,889 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-10:null) SeqA 2-90501: Sending Seq 2-90501: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:45,891 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-11:null) Ping from 2 > 2015-02-18 11:55:45,894 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-12:null) Ping from 3 > 2015-02-18 11:55:53,877 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-13:null) SeqA 2-90503: Processing Seq 2-90503: { Cmd > , MgmtId: -1, via: 2, Ver: v1, Flags: 11, > [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":6,"_loadInfo":"{\n > \"connections\": []\n}","wait":0}}] } > 2015-02-18 11:55:53,885 DEBUG [c.c.a.m.AgentManagerImpl] > (AgentManager-Handler-13:null) SeqA 2-90503: Sending Seq 2-90503: { Ans: , > MgmtId: 345052570767, via: 2, Ver: v1, Flags: 100010, > [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } > 2015-02-18 11:55:56,734 DEBUG [c.c.s.StatsCollector] > (StatsCollector-4:ctx-941a8b4f) AutoScaling Monitor is running... > 2015-02-18 11:55:57,078 DEBUG [c.c.s.StatsCollector] > (StatsCollector-1:ctx-ae7484bc) HostStatsCollector is running... > 2015-02-18 11:55:57,099 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-4:ctx-d5ca8cde) Seq 1-4574812796478291983: Executing request > 2015-02-18 11:55:57,159 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-4:ctx-d5ca8cde) Seq 1-4574812796478291983: Response Received: > 2015-02-18 11:55:57,160 DEBUG [c.c.a.t.Request] > (StatsCollector-1:ctx-ae7484bc) Seq 1-4574812796478291983: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetHostStatsAnswer } } > 2015-02-18 11:55:57,361 DEBUG [c.c.s.StatsCollector] > (StatsCollector-3:ctx-c4a555f2) StorageCollector is running... > 2015-02-18 11:55:57,436 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-c4a555f2) Seq 3-9163417866815406092: Received: { > Ans: , MgmtId: 345052570767, via: 3, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:55:57,445 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-8:ctx-da8dce01) Seq 1-4574812796478291984: Executing request > 2015-02-18 11:55:57,531 DEBUG [c.c.h.v.r.VmwareResource] > (DirectAgent-8:ctx-da8dce01 192.168.238.51) Datastore summary info, > storageId: 02afcc0e-83af-39d9-ab5e-5baba1b1aa72, localPath: > /FDatacenter/ESXi51Datastore, poolType: VMFS, capacity: 291789340672, free: > 54767124480, used: 237022216192 > 2015-02-18 11:55:57,532 DEBUG [c.c.a.m.DirectAgentAttache] > (DirectAgent-8:ctx-da8dce01) Seq 1-4574812796478291984: Response Received: > 2015-02-18 11:55:57,532 DEBUG [c.c.a.t.Request] > (StatsCollector-3:ctx-c4a555f2) Seq 1-4574812796478291984: Received: { > Ans: , MgmtId: 345052570767, via: 1, Ver: v1, Flags: 10, { > GetStorageStatsAnswer } } > 2015-02-18 11:55:57,575 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] > (secstorage-1:ctx-f750d7c1) Zone 1 is ready to launch secondary storage VM > 2015-02-18 11:55:58,307 DEBUG [c.c.c.ConsoleProxyManagerImpl] > (consoleproxy-1:ctx-60f3c780) Zone 1 is ready to launch console proxy > > > > ************************************************ > Regards, > José > -- Adriano Arantes Paterlini Analista de Sistemas Centro de Tecnologia da Informação - CeTI-SP Superintendência de Tecnologia da Informação - STI Universidade de São Paulo Fone: +55 (11) 3091-0494 Av. Professor Luciano Gualberto, 71, tv. 3 Cidade Universitária - São Paulo / SP
