Hi,
I have working cloudstack setup with 1 zone - 1 pod - 2 clusters.
Now I am getting the error "Unable to start a VM due to insufficient
capacity" when i try to start a VM.
the log says "The specified pod is in avoid set, returning".
Any hints?
thanks.
2014-11-26 16:13:07,924 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 28
2014-11-26 16:13:08,003 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 33
2014-11-26 16:13:08,648 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 35
2014-11-26 16:13:16,865 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 38-839346: Processing Seq 38-839346: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:13:16,946 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 38-839346: Sending Seq 38-839346: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:13:17,872 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-09595e91) VmStatsCollector is running...
2014-11-26 16:13:18,063 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-09595e91) Seq 35-1890517013: Received: { Ans: , MgmtId: 90581290632, via: 35, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-11-26 16:13:19,241 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-063014f7) StorageCollector is running...
2014-11-26 16:13:19,313 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-063014f7) Seq 39-909312013: Received: { Ans: , MgmtId: 90581290632, via: 39, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:13:19,498 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-92520df4) Zone 1 is ready to launch secondary storage VM
2014-11-26 16:13:19,629 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-063014f7) Seq 28-499318803: Received: { Ans: , MgmtId: 90581290632, via: 28, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:13:19,693 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-063014f7) Seq 29-1058603029: Received: { Ans: , MgmtId: 90581290632, via: 29, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:13:19,805 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-063014f7) Seq 33-995164175: Received: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:13:19,815 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-a3ebd2f7) Zone 1 is ready to launch console proxy
2014-11-26 16:13:26,831 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 38-839347: Processing Seq 38-839347: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:13:26,920 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 38-839347: Sending Seq 38-839347: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:13:28,991 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-2691fc62) HostStatsCollector is running...
2014-11-26 16:13:29,589 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2691fc62) Seq 28-499318804: Received: { Ans: , MgmtId: 90581290632, via: 28, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:13:29,618 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-20be3f80) ===START=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=1&pagesize=20&_=1416998072972
2014-11-26 16:13:29,898 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-20be3f80 ctx-7f638856) ===END=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=1&pagesize=20&_=1416998072972
2014-11-26 16:13:30,219 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2691fc62) Seq 29-1058603030: Received: { Ans: , MgmtId: 90581290632, via: 29, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:13:30,798 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2691fc62) Seq 33-995164176: Received: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:13:31,380 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-2691fc62) Seq 35-1890517014: Received: { Ans: , MgmtId: 90581290632, via: 35, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:13:31,776 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-63f537b1) Checking if any host reservation can be released ...
2014-11-26 16:13:31,808 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-63f537b1) Cannot release reservation, Found VM: VM[User|ellis] Stopped but reserved on host 28
2014-11-26 16:13:31,813 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-63f537b1) Cannot release reservation, Found 1 VMs Running on host 33
2014-11-26 16:13:31,818 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Running Capacity Checker ...
2014-11-26 16:13:31,818 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) recalculating system capacity
2014-11-26 16:13:31,818 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Executing cpu/ram capacity update
2014-11-26 16:13:31,824 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-63f537b1) Cannot release reservation, Found 7 VMs Running on host 35
2014-11-26 16:13:31,824 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HostReservationReleaseChecker:ctx-63f537b1) Done running HostReservationReleaseChecker ...
2014-11-26 16:13:31,828 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 0 VMs on host 28
2014-11-26 16:13:31,845 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 17 VM, not running on host 28
2014-11-26 16:13:31,855 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate cpu capacity, host:28 usedCpu: 0 reservedCpu: 3000
2014-11-26 16:13:31,855 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate memory capacity, host:28 usedMem: 0 reservedMem: 3221225472
2014-11-26 16:13:31,864 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 0 VMs on host 29
2014-11-26 16:13:31,874 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 5 VM, not running on host 29
2014-11-26 16:13:31,882 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate cpu capacity, host:29 usedCpu: 0 reservedCpu: 0
2014-11-26 16:13:31,882 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate memory capacity, host:29 usedMem: 0 reservedMem: 0
2014-11-26 16:13:31,890 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 0 VMs on host 31
2014-11-26 16:13:31,895 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 0 VM, not running on host 31
2014-11-26 16:13:31,897 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate cpu capacity, host:31 usedCpu: 0 reservedCpu: 0
2014-11-26 16:13:31,898 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate memory capacity, host:31 usedMem: 0 reservedMem: 0
2014-11-26 16:13:31,907 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 1 VMs on host 33
2014-11-26 16:13:31,919 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 6 VM, not running on host 33
2014-11-26 16:13:31,928 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate cpu capacity, host:33 usedCpu: 500 reservedCpu: 2000
2014-11-26 16:13:31,928 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate memory capacity, host:33 usedMem: 1073741824 reservedMem: 1073741824
2014-11-26 16:13:31,931 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-3eb940d8) ===START=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=2&pagesize=20&_=1416998075300
2014-11-26 16:13:31,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-07b4dc99) Found 0 routers to update status.
2014-11-26 16:13:31,939 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-07b4dc99) Found 0 networks to update RvR status.
2014-11-26 16:13:31,946 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 7 VMs on host 35
2014-11-26 16:13:31,960 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) Found 2 VM, not running on host 35
2014-11-26 16:13:31,966 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate cpu capacity, host:35 usedCpu: 27000 reservedCpu: 0
2014-11-26 16:13:31,966 DEBUG [c.c.c.CapacityManagerImpl] (CapacityChecker:ctx-83a345c2) No need to calibrate memory capacity, host:35 usedMem: 23756537856 reservedMem: 0
2014-11-26 16:13:31,966 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done executing cpu/ram capacity update
2014-11-26 16:13:31,966 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Executing storage capacity update
2014-11-26 16:13:32,078 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-83a345c2) Successfully set Capacity - 972546375680 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 2, PodId 1
2014-11-26 16:13:32,129 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-3eb940d8 ctx-044edf6e) ===END=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=2&pagesize=20&_=1416998075300
2014-11-26 16:13:32,186 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-83a345c2) Successfully set Capacity - 7251091128320 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 10, PodId 1
2014-11-26 16:13:32,295 DEBUG [c.c.s.StorageManagerImpl] (CapacityChecker:ctx-83a345c2) Successfully set Capacity - 7034645184512 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 11, PodId 1
2014-11-26 16:13:32,295 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done executing storage capacity update
2014-11-26 16:13:32,295 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Executing capacity updates for public ip and Vlans
2014-11-26 16:13:32,304 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done capacity updates for public ip and Vlans
2014-11-26 16:13:32,304 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Executing capacity updates for private ip
2014-11-26 16:13:32,312 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done executing capacity updates for private ip
2014-11-26 16:13:32,312 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done recalculating system capacity
2014-11-26 16:13:32,342 DEBUG [c.c.a.AlertManagerImpl] (CapacityChecker:ctx-83a345c2) Done running Capacity Checker ...
2014-11-26 16:13:34,244 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-5656d6db) ===START=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=3&pagesize=20&_=1416998077584
2014-11-26 16:13:34,324 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-5656d6db ctx-a56f3e6d) ===END=== 10.129.34.97 -- GET command=listVirtualMachines&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&listAll=true&page=3&pagesize=20&_=1416998077584
2014-11-26 16:13:36,832 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 38-839348: Processing Seq 38-839348: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:13:36,895 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) SeqA 38-839348: Sending Seq 38-839348: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:13:41,832 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 38-839349: Processing Seq 38-839349: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:13:41,911 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 38-839349: Sending Seq 38-839349: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:13:49,495 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-61c75348) Zone 1 is ready to launch secondary storage VM
2014-11-26 16:13:49,813 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-370a92e6) Zone 1 is ready to launch console proxy
2014-11-26 16:13:51,834 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 38-839350: Processing Seq 38-839350: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:13:51,909 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-3:null) SeqA 38-839350: Sending Seq 38-839350: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:01,835 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 38-839351: Processing Seq 38-839351: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:01,917 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 38-839351: Sending Seq 38-839351: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:01,937 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-80ba6668) Found 0 routers to update status.
2014-11-26 16:14:01,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-80ba6668) Found 0 networks to update RvR status.
2014-11-26 16:14:03,309 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) Ping from 29
2014-11-26 16:14:03,329 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 24
2014-11-26 16:14:06,830 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Resetting hosts suitable for reconnect
2014-11-26 16:14:06,832 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Completed resetting hosts suitable for reconnect
2014-11-26 16:14:06,832 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Acquiring hosts for clusters already owned by this management server
2014-11-26 16:14:06,833 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Completed acquiring hosts for clusters already owned by this management server
2014-11-26 16:14:06,833 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Acquiring hosts for clusters not owned by any management server
2014-11-26 16:14:06,833 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-388f4e20) Completed acquiring hosts for clusters not owned by any management server
2014-11-26 16:14:06,836 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 38-839352: Processing Seq 38-839352: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:06,900 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 38-839352: Sending Seq 38-839352: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:07,051 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) Ping from 39
2014-11-26 16:14:07,232 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 38
2014-11-26 16:14:07,926 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 28
2014-11-26 16:14:08,004 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 33
2014-11-26 16:14:08,655 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) Ping from 35
2014-11-26 16:14:16,873 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 38-839354: Processing Seq 38-839354: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:16,956 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 38-839354: Sending Seq 38-839354: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:18,064 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-8617d66b) VmStatsCollector is running...
2014-11-26 16:14:18,263 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-8617d66b) Seq 35-1890517015: Received: { Ans: , MgmtId: 90581290632, via: 35, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2014-11-26 16:14:19,496 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-74a0414d) Zone 1 is ready to launch secondary storage VM
2014-11-26 16:14:19,806 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-05fe27e5) StorageCollector is running...
2014-11-26 16:14:19,814 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-67809e13) Zone 1 is ready to launch console proxy
2014-11-26 16:14:19,877 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-05fe27e5) Seq 39-909312014: Received: { Ans: , MgmtId: 90581290632, via: 39, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:14:20,173 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-05fe27e5) Seq 29-1058603031: Received: { Ans: , MgmtId: 90581290632, via: 29, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:14:20,236 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-05fe27e5) Seq 29-1058603032: Received: { Ans: , MgmtId: 90581290632, via: 29, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:14:20,348 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-05fe27e5) Seq 33-995164177: Received: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2014-11-26 16:14:26,838 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 38-839355: Processing Seq 38-839355: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:26,922 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-4:null) SeqA 38-839355: Sending Seq 38-839355: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:31,380 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-6b5121b3) HostStatsCollector is running...
2014-11-26 16:14:31,839 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 38-839356: Processing Seq 38-839356: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:31,930 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-5:null) SeqA 38-839356: Sending Seq 38-839356: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:31,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-f01d8e7b) Found 0 routers to update status.
2014-11-26 16:14:31,939 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-f01d8e7b) Found 0 networks to update RvR status.
2014-11-26 16:14:32,017 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-6b5121b3) Seq 28-499318805: Received: { Ans: , MgmtId: 90581290632, via: 28, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:14:32,646 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-6b5121b3) Seq 29-1058603033: Received: { Ans: , MgmtId: 90581290632, via: 29, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:14:33,223 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-6b5121b3) Seq 33-995164178: Received: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:14:33,805 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-6b5121b3) Seq 35-1890517016: Received: { Ans: , MgmtId: 90581290632, via: 35, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2014-11-26 16:14:35,420 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-5b4e5d9a) ===START=== 10.129.34.97 -- GET command=listZones&id=f64b5a68-2c69-4034-b025-ce702d171b0c&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138785
2014-11-26 16:14:35,435 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-5b4e5d9a ctx-88f83e3e) ===END=== 10.129.34.97 -- GET command=listZones&id=f64b5a68-2c69-4034-b025-ce702d171b0c&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138785
2014-11-26 16:14:35,472 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-9ffa93b9) ===START=== 10.129.34.97 -- GET command=listNetworks&id=20c7764a-7cd4-4381-93eb-bf23d1f9793f&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138844
2014-11-26 16:14:35,538 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-9ffa93b9 ctx-66c18492) ===END=== 10.129.34.97 -- GET command=listNetworks&id=20c7764a-7cd4-4381-93eb-bf23d1f9793f&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138844
2014-11-26 16:14:35,564 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-b0501591) ===START=== 10.129.34.97 -- GET command=listVirtualMachines&id=2ccd74a7-5226-419a-84cc-25cea9957f01&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138927
2014-11-26 16:14:35,605 DEBUG [c.c.a.ApiServlet] (catalina-exec-3:ctx-b0501591 ctx-ec8d47ed) ===END=== 10.129.34.97 -- GET command=listVirtualMachines&id=2ccd74a7-5226-419a-84cc-25cea9957f01&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138927
2014-11-26 16:14:35,672 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-07504495) ===START=== 10.129.34.97 -- GET command=listOsTypes&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138991
2014-11-26 16:14:35,893 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-07504495 ctx-d0408a0f) ===END=== 10.129.34.97 -- GET command=listOsTypes&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998138991
2014-11-26 16:14:41,841 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 38-839357: Processing Seq 38-839357: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:41,937 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 38-839357: Sending Seq 38-839357: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:43,213 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-d594de3a) ===START=== 10.129.34.97 -- GET command=startVirtualMachine&id=2ccd74a7-5226-419a-84cc-25cea9957f01&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998146574
2014-11-26 16:14:43,464 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (catalina-exec-5:ctx-d594de3a ctx-c12a818e) submit async job-3874, details: AsyncJobVO {id:3874, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 168, cmd: org.apache.cloudstack.api.command.user.vm.StartVMCmd, cmdInfo: {"id":"2ccd74a7-5226-419a-84cc-25cea9957f01","response":"json","sessionkey":"S/7fHYLg79EioNVva86gRDHNcPY\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1416998146574","ctxAccountId":"2","ctxStartEventId":"12140"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90581290632, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-26 16:14:43,465 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-1:ctx-300e8909) Add job-3874 into job monitoring
2014-11-26 16:14:43,465 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-1:ctx-300e8909) Executing AsyncJobVO {id:3874, userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 168, cmd: org.apache.cloudstack.api.command.user.vm.StartVMCmd, cmdInfo: {"id":"2ccd74a7-5226-419a-84cc-25cea9957f01","response":"json","sessionkey":"S/7fHYLg79EioNVva86gRDHNcPY\u003d","cmdEventType":"VM.START","ctxUserId":"2","httpmethod":"GET","_":"1416998146574","ctxAccountId":"2","ctxStartEventId":"12140"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 90581290632, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-26 16:14:43,467 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-d594de3a ctx-c12a818e) ===END=== 10.129.34.97 -- GET command=startVirtualMachine&id=2ccd74a7-5226-419a-84cc-25cea9957f01&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998146574
2014-11-26 16:14:43,667 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [], clusters: [], hosts: []
2014-11-26 16:14:43,668 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:14:43,668 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2014-11-26 16:14:43,668 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-26 16:14:43,669 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) This VM has last host_id specified, trying to choose the same host: 28
2014-11-26 16:14:43,676 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Checking if host: 28 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Hosts's actual total CPU: 18088 and CPU after applying overprovisioning: 18088
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) We need to allocate to the last host again, so checking if there is enough reserved capacity
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Reserved CPU: 3000 , Requested CPU: 500
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Reserved RAM: 3221225472 , Requested RAM: 536870912
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Host has enough CPU and RAM available
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) STATS: Can alloc CPU from host: 28, used: 0, reserved: 3000, actual total: 18088, total with overprovisioning: 18088; requested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true
2014-11-26 16:14:43,679 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) STATS: Can alloc MEM from host: 28, used: 0, reserved: 3221225472, total: 25272963072; requested mem: 536870912,alloc_from_last_host?:true ,considerReservedCapacity?: true
2014-11-26 16:14:43,681 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Host: 28 has cpu capability (cpu:8, speed:2261) to support requested CPU: 1 and requested speed: 500
2014-11-26 16:14:43,681 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The last host of this VM is UP and has enough capacity
2014-11-26 16:14:43,681 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
2014-11-26 16:14:43,684 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Checking suitable pools for volume (Id, Type): (318,ROOT)
2014-11-26 16:14:43,685 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Volume has pool already allocated, checking if pool can be reused, poolId: 2
2014-11-26 16:14:43,686 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Planner need not allocate a pool for this volume since its READY
2014-11-26 16:14:43,687 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-11-26 16:14:43,688 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Checking if host: 28 can access any suitable storage pool for volume: ROOT
2014-11-26 16:14:43,690 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Host: 28 can access pool: 2
2014-11-26 16:14:43,691 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Found a potential host id: 28 name: host3 and associated storage pools for this VM
2014-11-26 16:14:43,692 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(28)-Storage()]
2014-11-26 16:14:43,837 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 28 new host id: null host id before state transition: null
2014-11-26 16:14:43,837 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Successfully transitioned to start state for VM[User|kerneltest] reservation id = b3f38c97-af47-4214-b4d3-223cdb4f9f2c
2014-11-26 16:14:43,921 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to deploy VM, vm has dcId: 1 and podId: 1
2014-11-26 16:14:43,921 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 28, poolId: null
2014-11-26 16:14:43,921 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: null, clusters: null, hosts: null
2014-11-26 16:14:43,926 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Root volume is ready, need to place VM in volume's cluster
2014-11-26 16:14:43,934 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [], clusters: [], hosts: []
2014-11-26 16:14:43,936 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:14:43,936 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2014-11-26 16:14:43,936 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-26 16:14:43,936 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 28
2014-11-26 16:14:43,937 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2014-11-26 16:14:43,939 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Checking suitable pools for volume (Id, Type): (318,ROOT)
2014-11-26 16:14:43,939 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Volume has pool already allocated, checking if pool can be reused, poolId: 2
2014-11-26 16:14:43,941 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Planner need not allocate a pool for this volume since its READY
2014-11-26 16:14:43,941 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2014-11-26 16:14:43,941 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Checking if host: 28 can access any suitable storage pool for volume: ROOT
2014-11-26 16:14:43,942 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Host: 28 can access pool: 2
2014-11-26 16:14:43,943 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Found a potential host id: 28 name: host3 and associated storage pools for this VM
2014-11-26 16:14:43,944 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(28)-Storage()]
2014-11-26 16:14:43,944 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deployment found - P0=VM[User|kerneltest], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(28)-Storage()]
2014-11-26 16:14:44,413 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 28 new host id: 28 host id before state transition: null
2014-11-26 16:14:44,413 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM starting again on the last host it was stopped on
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Hosts's actual total CPU: 18088 and CPU after applying overprovisioning: 18088
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) We are allocating VM, increasing the used capacity of this host:28
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Current Used CPU: 0 , Free CPU:15088 ,Requested CPU: 500
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Current Used RAM: 0 , Free RAM:22051737600 ,Requested RAM: 536870912
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Reserved CPU: 3000 , Requested CPU: 500
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Reserved RAM: 3221225472 , Requested RAM: 536870912
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) CPU STATS after allocation: for host: 28, old used: 0, old reserved: 3000, actual total: 18088, total with overprovisioning: 18088; new used:500, reserved:2500; requested cpu:500,alloc_from_last:true
2014-11-26 16:14:44,424 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) RAM STATS after allocation: for host: 28, old used: 0, old reserved: 3221225472, total: 25272963072; new used: 536870912, reserved: 2684354560; requested mem: 536870912,alloc_from_last:true
2014-11-26 16:14:44,505 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM is being created in podId: 1
2014-11-26 16:14:44,514 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Network id=204 is already implemented
2014-11-26 16:14:44,636 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Changing active number of nics for network id=204 on 1
2014-11-26 16:14:44,727 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Asking VirtualRouter to prepare for Nic[209-168-b3f38c97-af47-4214-b4d3-223cdb4f9f2c-10.129.34.69]
2014-11-26 16:14:44,743 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Lock is acquired for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(28)-Storage()]
2014-11-26 16:14:44,748 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Lock is released for network id 204 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(28)-Storage()]
2014-11-26 16:14:44,785 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Applying dhcp entry in network Ntwk[204|Guest|6]
2014-11-26 16:14:44,808 DEBUG [c.c.a.t.Request] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Seq 33-995164179: Sending { Cmd , MgmtId: 90581290632, via: 33(host7), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:0d:54:00:00:32","vmIpAddress":"10.129.34.69","vmName":"kerneltest","defaultRouter":"10.129.250.1","defaultDns":"10.129.34.74","duid":"00:03:00:01:06:0d:54:00:00:32","isDefault":true,"executeInSequence":true,"accessDetails":{"router.guest.ip":"10.129.34.74","zone.network.type":"Basic","router.name":"r-167-VM","router.ip":"169.254.3.192"},"wait":0}}] }
2014-11-26 16:14:46,526 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-fee2c305) ===START=== 10.129.34.97 -- GET command=queryAsyncJobResult&jobId=a390923e-fb05-4c0b-b411-ae24ba098599&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998149863
2014-11-26 16:14:46,646 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-fee2c305 ctx-5022ab5a) ===END=== 10.129.34.97 -- GET command=queryAsyncJobResult&jobId=a390923e-fb05-4c0b-b411-ae24ba098599&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998149863
2014-11-26 16:14:47,834 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) Seq 33-995164179: Processing: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"ssh: connect to host 169.254.3.192 port 3922: No route to host","wait":0}}] }
2014-11-26 16:14:47,834 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-11:null) Seq 33-995164179: No more commands found
2014-11-26 16:14:47,834 DEBUG [c.c.a.t.Request] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Seq 33-995164179: Received: { Ans: , MgmtId: 90581290632, via: 33, Ver: v1, Flags: 110, { Answer } }
2014-11-26 16:14:47,835 INFO [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Unable to contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [Pod:1] is unreachable: Unable to apply dhcp entry on router
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3913)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3043)
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:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy240.applyDhcpEntry(Unknown Source)
at com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:921)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1187)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1309)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1245)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:960)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:228)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2043)
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:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:121)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
2014-11-26 16:14:47,923 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Cleaning up resources for the vm VM[User|kerneltest] in Starting state
2014-11-26 16:14:47,926 DEBUG [c.c.a.t.Request] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Seq 28-499318806: Sending { Cmd , MgmtId: 90581290632, via: 28(host3), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-31-168-VM","wait":0}}] }
2014-11-26 16:14:48,123 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:null) Seq 28-499318806: Processing: { Ans: , MgmtId: 90581290632, via: 28, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:48,123 DEBUG [c.c.a.t.Request] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Seq 28-499318806: Received: { Ans: , MgmtId: 90581290632, via: 28, Ver: v1, Flags: 10, { StopAnswer } }
2014-11-26 16:14:48,137 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Changing active number of nics for network id=204 on -1
2014-11-26 16:14:48,260 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Asking VirtualRouter to release NicProfile[209-168-b3f38c97-af47-4214-b4d3-223cdb4f9f2c-10.129.34.69-vlan://untagged
2014-11-26 16:14:48,262 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Asking SecurityGroupProvider to release NicProfile[209-168-b3f38c97-af47-4214-b4d3-223cdb4f9f2c-10.129.34.69-vlan://untagged
2014-11-26 16:14:48,264 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Successfully released network resources for the vm VM[User|kerneltest]
2014-11-26 16:14:48,264 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Successfully cleanued up resources for the vm VM[User|kerneltest] in Starting state
2014-11-26 16:14:48,266 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Root volume is ready, need to place VM in volume's cluster
2014-11-26 16:14:48,274 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [1], clusters: [], hosts: [28]
2014-11-26 16:14:48,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:14:48,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2014-11-26 16:14:48,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-26 16:14:48,275 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 28
2014-11-26 16:14:48,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The specified host is in avoid set
2014-11-26 16:14:48,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Cannnot deploy to specified host, returning.
2014-11-26 16:14:48,507 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 28 new host id: null host id before state transition: 28
2014-11-26 16:14:48,516 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Hosts's actual total CPU: 18088 and CPU after applying overprovisioning: 18088
2014-11-26 16:14:48,516 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Hosts's actual total RAM: 25272963072 and RAM after applying overprovisioning: 25272963072
2014-11-26 16:14:48,516 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) release cpu from host: 28, old used: 500,reserved: 2500, actual total: 18088, total with overprovisioning: 18088; new used: 0,reserved:2500; movedfromreserved: false,moveToReserveredfalse
2014-11-26 16:14:48,516 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) release mem from host: 28, old used: 536870912,reserved: 2684354560, total: 25272963072; new used: 0,reserved:2684354560; movedfromreserved: false,moveToReserveredfalse
2014-11-26 16:14:48,672 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 28 new host id: null host id before state transition: null
2014-11-26 16:14:48,673 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Successfully transitioned to start state for VM[User|kerneltest] reservation id = 7537c4b0-2c34-4de5-8b0e-b81cdd037484
2014-11-26 16:14:48,749 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to deploy VM, vm has dcId: 1 and podId: 1
2014-11-26 16:14:48,749 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [1], clusters: [], hosts: [28]
2014-11-26 16:14:48,753 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Root volume is ready, need to place VM in volume's cluster
2014-11-26 16:14:48,753 DEBUG [c.c.v.VirtualMachineManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Vol[318|vm=168|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2014-11-26 16:14:48,761 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [1], clusters: [], hosts: [28]
2014-11-26 16:14:48,762 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:14:48,762 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
2014-11-26 16:14:48,762 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-26 16:14:48,762 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) This VM has last host_id specified, trying to choose the same host: 28
2014-11-26 16:14:48,763 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The last host of this VM is in avoid set
2014-11-26 16:14:48,763 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Cannot choose the last host to deploy this VM
2014-11-26 16:14:48,764 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Searching resources only under specified Cluster: 1
2014-11-26 16:14:48,765 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The specified cluster is in avoid set, returning.
2014-11-26 16:14:48,773 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Deploy avoids pods: [1], clusters: [], hosts: [28]
2014-11-26 16:14:48,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:14:48,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2014-11-26 16:14:48,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Is ROOT volume READY (pool already allocated)?: No
2014-11-26 16:14:48,774 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) This VM has last host_id specified, trying to choose the same host: 28
2014-11-26 16:14:48,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The last host of this VM is in avoid set
2014-11-26 16:14:48,775 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Cannot choose the last host to deploy this VM
2014-11-26 16:14:48,775 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) Searching resources only under specified Pod: 1
2014-11-26 16:14:48,775 DEBUG [c.c.d.FirstFitPlanner] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) The specified pod is in avoid set, returning.
2014-11-26 16:14:48,926 DEBUG [c.c.c.CapacityManagerImpl] (Job-Executor-1:ctx-300e8909 ctx-c12a818e) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 28 new host id: null host id before state transition: null
2014-11-26 16:14:49,084 ERROR [c.c.a.ApiAsyncJobDispatcher] (Job-Executor-1:ctx-300e8909) Unexpected exception while executing org.apache.cloudstack.api.command.user.vm.StartVMCmd
com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM due to insufficient capacity
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:605)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:207)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3581)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2043)
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:622)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy169.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.user.vm.StartVMCmd.execute(StartVMCmd.java:121)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:701)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|kerneltest]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:921)
at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:761)
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:601)
... 37 more
2014-11-26 16:14:49,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-1:ctx-300e8909) Complete async job-3874, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Unable to start a VM due to insufficient capacity"}
2014-11-26 16:14:49,175 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Executor-1:ctx-300e8909) Done executing org.apache.cloudstack.api.command.user.vm.StartVMCmd for job-3874
2014-11-26 16:14:49,217 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-1:ctx-300e8909) Remove job-3874 from job monitoring
2014-11-26 16:14:49,491 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-11b914e7) ===START=== 10.129.34.97 -- GET command=queryAsyncJobResult&jobId=a390923e-fb05-4c0b-b411-ae24ba098599&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998152863
2014-11-26 16:14:49,494 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-a2ddad1b) Zone 1 is ready to launch secondary storage VM
2014-11-26 16:14:49,588 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-11b914e7 ctx-2ca758e6) ===END=== 10.129.34.97 -- GET command=queryAsyncJobResult&jobId=a390923e-fb05-4c0b-b411-ae24ba098599&response=json&sessionkey=S%2F7fHYLg79EioNVva86gRDHNcPY%3D&_=1416998152863
2014-11-26 16:14:49,811 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-274fa753) Zone 1 is ready to launch console proxy
2014-11-26 16:14:51,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 38-839358: Processing Seq 38-839358: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:51,917 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 38-839358: Sending Seq 38-839358: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:14:56,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 38-839359: Processing Seq 38-839359: { Cmd , MgmtId: -1, via: 38, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":248,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-26 16:14:56,934 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 38-839359: Sending Seq 38-839359: { Ans: , MgmtId: 90581290632, via: 38, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-26 16:15:01,938 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7756923f) Found 0 routers to update status.
2014-11-26 16:15:01,939 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-7756923f) Found 0 networks to update RvR status.
2014-11-26 16:15:02,093 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Processing HAWork[192-HA-582-Stopped-Scheduled]
2014-11-26 16:15:02,099 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) HA on VM[User|VM-43c80ff8-d020-4248-9699-a58b4c6d2576]
2014-11-26 16:15:02,106 WARN [o.a.c.f.j.AsyncJobExecutionContext] (HA-Worker-1:ctx-05aac19d work-192) Job is executed without a context, setup psudo job for the executing thread
2014-11-26 16:15:02,193 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-4:ctx-5de2de47 work-202) Processing HAWork[202-HA-581-Stopped-Scheduled]
2014-11-26 16:15:02,198 INFO [c.c.h.HighAvailabilityManagerImpl] (HA-Worker-4:ctx-5de2de47 work-202) HA on VM[User|VM-740117b6-d366-4538-94c7-8ad7268028d4]
2014-11-26 16:15:02,204 WARN [o.a.c.f.j.AsyncJobExecutionContext] (HA-Worker-4:ctx-5de2de47 work-202) Job is executed without a context, setup psudo job for the executing thread
2014-11-26 16:15:02,251 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 28 new host id: null host id before state transition: null
2014-11-26 16:15:02,251 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Successfully transitioned to start state for VM[User|VM-43c80ff8-d020-4248-9699-a58b4c6d2576] reservation id = e0bfc11d-c4fc-463c-b731-3fb62aab2965
2014-11-26 16:15:02,354 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-4:ctx-5de2de47 work-202) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 28 new host id: null host id before state transition: null
2014-11-26 16:15:02,354 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-4:ctx-5de2de47 work-202) Successfully transitioned to start state for VM[User|VM-740117b6-d366-4538-94c7-8ad7268028d4] reservation id = 3e5406e0-4b30-48ac-ba8a-92a56b941813
2014-11-26 16:15:02,395 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Trying to deploy VM, vm has dcId: 1 and podId: 1
2014-11-26 16:15:02,395 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Deploy avoids pods: null, clusters: null, hosts: null
2014-11-26 16:15:02,398 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Root volume is ready, need to place VM in volume's cluster
2014-11-26 16:15:02,399 DEBUG [c.c.v.VirtualMachineManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Vol[740|vm=582|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
2014-11-26 16:15:02,406 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Deploy avoids pods: [], clusters: [], hosts: []
2014-11-26 16:15:02,407 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@129e49c0
2014-11-26 16:15:02,408 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824
2014-11-26 16:15:02,408 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Is ROOT volume READY (pool already allocated)?: Yes
2014-11-26 16:15:02,408 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) This VM has last host_id specified, trying to choose the same host: 28
2014-11-26 16:15:02,413 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Checking if host: 28 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Hosts's actual total CPU: 18088 and CPU after applying overprovisioning: 18088
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) We need to allocate to the last host again, so checking if there is enough reserved capacity
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Reserved CPU: 2500 , Requested CPU: 1000
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Reserved RAM: 2684354560 , Requested RAM: 1073741824
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Host has enough CPU and RAM available
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) STATS: Can alloc CPU from host: 28, used: 0, reserved: 2500, actual total: 18088, total with overprovisioning: 18088; requested cpu:1000,alloc_from_last_host?:true ,considerReservedCapacity?: true
2014-11-26 16:15:02,416 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) STATS: Can alloc MEM from host: 28, used: 0, reserved: 2684354560, total: 25272963072; requested mem: 1073741824,alloc_from_last_host?:true ,considerReservedCapacity?: true
2014-11-26 16:15:02,417 DEBUG [c.c.c.CapacityManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Host: 28 has cpu capability (cpu:8, speed:2261) to support requested CPU: 1 and requested speed: 1000
2014-11-26 16:15:02,417 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) The last host of this VM is UP and has enough capacity
2014-11-26 16:15:02,417 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Now checking for suitable pools under zone: 1, pod: 1, cluster: 1
2014-11-26 16:15:02,420 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Checking suitable pools for volume (Id, Type): (740,ROOT)
2014-11-26 16:15:02,420 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Volume has pool already allocated, checking if pool can be reused, poolId: 2
2014-11-26 16:15:02,421 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (HA-Worker-1:ctx-05aac19d work-192) Planner need not allocate a pool for this volume since its READY
