cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From José Egas López <josee...@farmaenlace.com>
Subject RE: Error when changing Service offering
Date Wed, 18 Feb 2015 20:42:17 GMT
Thank you Adriano, that's right!
I skipped it.


Regards,
José
 
-----Mensaje original-----
De: Adriano Paterlini [mailto:paterlini@usp.br] 
Enviado el: miércoles, 18 de febrero de 2015 15:18
Para: users@cloudstack.apache.org
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 <joseegas@farmaenlace.com>
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


Mime
View raw message