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é
