You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Nagaraju (JIRA)" <ji...@apache.org> on 2015/04/06 08:18:14 UTC
[jira] [Commented] (CLOUDSTACK-8359) After restarting KVm
[ https://issues.apache.org/jira/browse/CLOUDSTACK-8359?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14480975#comment-14480975 ]
Nagaraju commented on CLOUDSTACK-8359:
--------------------------------------
HI Rajani,
Below is the log details,
se,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"s-5589-VM","wait":0}}] }
2015-04-06 11:46:06,319 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-2d94718f) ===START=== 172.21.8.92 -- GET command=listZones&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969298
2015-04-06 11:46:06,331 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-22:ctx-2d94718f ctx-54174938) Received unknown parameters for command listZones. Unknown parameters : listall
2015-04-06 11:46:06,345 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-2d94718f ctx-54174938) ===END=== 172.21.8.92 -- GET command=listZones&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969298
2015-04-06 11:46:06,412 DEBUG [c.c.a.t.Request] (AgentManager-Handler-7:null) Seq 1-6592706904517007133: Processing: { Ans: , MgmtId: 345050277750, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-04-06 11:46:06,413 DEBUG [c.c.a.t.Request] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Seq 1-6592706904517007133: Received: { Ans: , MgmtId: 345050277750, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2015-04-06 11:46:06,426 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Released nic: NicProfile[22353-5589-null-null-null
2015-04-06 11:46:06,437 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Releasing ip address for reservationId=6fcde50c-db8c-4827-91ef-a4c2480d248f, instance=22354
2015-04-06 11:46:06,438 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Released nic: NicProfile[22354-5589-null-null-null
2015-04-06 11:46:06,451 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Releasing ip address for reservationId=6fcde50c-db8c-4827-91ef-a4c2480d248f, instance=22355
2015-04-06 11:46:06,451 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Released nic: NicProfile[22355-5589-null-null-null
2015-04-06 11:46:06,455 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Successfully released network resources for the vm VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:06,455 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-5589-VM] in Starting state
2015-04-06 11:46:06,460 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Deploy avoids pods: [1], clusters: null, hosts: [1]
2015-04-06 11:46:06,461 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5977abd5
2015-04-06 11:46:06,461 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
2015-04-06 11:46:06,461 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Is ROOT volume READY (pool already allocated)?: No
2015-04-06 11:46:06,462 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Searching all possible resources under this Zone: 1
2015-04-06 11:46:06,464 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2015-04-06 11:46:06,478 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Checking resources in Cluster: 1 under Pod: 1
2015-04-06 11:46:06,478 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2015-04-06 11:46:06,482 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-04-06 11:46:06,489 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-04-06 11:46:06,489 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2015-04-06 11:46:06,490 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) Host name: ctkvm1, hostId: 1 is in avoid set, skipping this and trying other available hosts
2015-04-06 11:46:06,490 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2015-04-06 11:46:06,490 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) No suitable hosts found
2015-04-06 11:46:06,490 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) No suitable hosts found under this Cluster: 1
2015-04-06 11:46:06,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Could not find suitable Deployment Destination for this VM under any clusters, returning.
2015-04-06 11:46:06,493 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Searching all possible resources under this Zone: 1
2015-04-06 11:46:06,495 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
2015-04-06 11:46:06,502 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Removing from the clusterId list these clusters from avoid set: [1]
2015-04-06 11:46:06,504 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) No clusters found after removing disabled clusters and clusters in avoid list, returning.
2015-04-06 11:46:06,516 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2015-04-06 11:46:06,525 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-06 11:46:06,525 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Hosts's actual total RAM: 20958195712 and RAM after applying overprovisioning: 20958195712
2015-04-06 11:46:06,525 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-06 11:46:06,525 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) release mem from host: 1, old used: 1610612736,reserved: 0, total: 20958195712; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-06 11:46:06,528 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-06 11:46:06,528 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795 ctx-60da4339) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-06 11:46:06,528 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 5589, job origin: 1
2015-04-06 11:46:06,528 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Unable to complete AsyncJobVO {id:16795, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAV1XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 06 11:46:05 IST 2015}, job origin:1
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-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.GeneratedMethodAccessor281.invoke(Unknown Source)
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-04-06 11:46:06,531 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Complete async job-16795, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAXkpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bU2Vjb25kYXJ5U3RvcmFnZVZtfHMtNTU4OS1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-04-06 11:46:06,546 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Done executing com.cloud.vm.VmWorkStart for job-16795
2015-04-06 11:46:06,564 WARN [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-e80fb0db) Exception while trying to start secondary storage vm
java.lang.RuntimeException: Job failed due to exception Unable to create a deployment for VM[SecondaryStorageVm|s-5589-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-04-06 11:46:06,565 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-e80fb0db) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 5589, will recycle it and start a new one
2015-04-06 11:46:06,565 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-e80fb0db) Primary secondary storage is not even started, wait until next turn
2015-04-06 11:46:06,570 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Sync queue (16765) is currently empty
2015-04-06 11:46:06,570 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-165:ctx-60d04d1d job-1/job-16795) Remove job-16795 from job monitoring
2015-04-06 11:46:06,580 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-09c90212) ===START=== 172.21.8.92 -- GET command=listPods&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969568
2015-04-06 11:46:06,583 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-1:ctx-09c90212 ctx-179268a1) Received unknown parameters for command listPods. Unknown parameters : listall
2015-04-06 11:46:06,589 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-09c90212 ctx-179268a1) ===END=== 172.21.8.92 -- GET command=listPods&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969568
2015-04-06 11:46:06,723 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-50bf8708) ===START=== 172.21.8.92 -- GET command=listClusters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969714
2015-04-06 11:46:06,730 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-16:ctx-50bf8708 ctx-9ec3ad92) Received unknown parameters for command listClusters. Unknown parameters : listall
2015-04-06 11:46:06,741 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-50bf8708 ctx-9ec3ad92) ===END=== 172.21.8.92 -- GET command=listClusters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300969714
2015-04-06 11:46:06,937 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-d9e21b5b) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=1&_=1428300969926
2015-04-06 11:46:06,944 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-11:ctx-d9e21b5b ctx-0f23c2c1) Received unknown parameters for command listHosts. Unknown parameters : listall
2015-04-06 11:46:06,944 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-11:ctx-d9e21b5b ctx-0f23c2c1) >>>Searching for hosts>>>
2015-04-06 11:46:06,954 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-11:ctx-d9e21b5b ctx-0f23c2c1) >>>Generating Response>>>
2015-04-06 11:46:06,963 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-d9e21b5b ctx-0f23c2c1) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=1&_=1428300969926
2015-04-06 11:46:07,018 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-edec42cb) Expunge completed work job-16793
2015-04-06 11:46:07,023 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-edec42cb) Expunge completed work job-16794
2015-04-06 11:46:07,028 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-edec42cb) Expunge completed work job-16795
2015-04-06 11:46:07,248 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-5696231a) ===START=== 172.21.8.92 -- GET command=listStoragePools&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970236
2015-04-06 11:46:07,256 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-24:ctx-5696231a ctx-cb4227bd) Received unknown parameters for command listStoragePools. Unknown parameters : listall
2015-04-06 11:46:07,273 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-5696231a ctx-cb4227bd) ===END=== 172.21.8.92 -- GET command=listStoragePools&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970236
2015-04-06 11:46:07,332 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-36b45712) ===START=== 172.21.8.92 -- GET command=listImageStores&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=SecondaryStorage&listAll=true&page=1&pagesize=1&_=1428300970373
2015-04-06 11:46:07,342 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-10:ctx-36b45712 ctx-e4fbc4fb) Received unknown parameters for command listImageStores. Unknown parameters : listall type
2015-04-06 11:46:07,362 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-36b45712 ctx-e4fbc4fb) ===END=== 172.21.8.92 -- GET command=listImageStores&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=SecondaryStorage&listAll=true&page=1&pagesize=1&_=1428300970373
2015-04-06 11:46:07,374 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-338b887e) ===START=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970433
2015-04-06 11:46:07,384 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-19:ctx-338b887e ctx-7dafde5b) Received unknown parameters for command listSystemVms. Unknown parameters : listall
2015-04-06 11:46:07,474 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-338b887e ctx-7dafde5b) ===END=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970433
2015-04-06 11:46:07,487 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-fe90e757) ===START=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970541
2015-04-06 11:46:07,510 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-fe90e757 ctx-9c719233) ===END=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300970541
2015-04-06 11:46:07,516 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-454ff8e0) ===START=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&projectid=-1&page=1&pagesize=1&_=1428300970576
2015-04-06 11:46:07,533 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-454ff8e0 ctx-025d6cc2) ===END=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&projectid=-1&page=1&pagesize=1&_=1428300970576
2015-04-06 11:46:07,540 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-7928f51a) ===START=== 172.21.8.92 -- GET command=listCapacity&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300970599
2015-04-06 11:46:07,580 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-7928f51a ctx-d2ac15e8) ===END=== 172.21.8.92 -- GET command=listCapacity&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300970599
2015-04-06 11:46:07,609 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-8b953339) ===START=== 172.21.8.92 -- GET command=listHypervisors&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300970664
2015-04-06 11:46:07,621 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-8b953339 ctx-041c4fb8) ===END=== 172.21.8.92 -- GET command=listHypervisors&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300970664
2015-04-06 11:46:07,637 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-c08ee0a0) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Hyperv&page=1&pagesize=20&_=1428300970697
2015-04-06 11:46:07,647 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-17:ctx-c08ee0a0 ctx-71576e6d) >>>Searching for hosts>>>
2015-04-06 11:46:07,655 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-17:ctx-c08ee0a0 ctx-71576e6d) >>>Generating Response>>>
2015-04-06 11:46:07,656 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-c08ee0a0 ctx-71576e6d) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Hyperv&page=1&pagesize=20&_=1428300970697
2015-04-06 11:46:07,663 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-a20f5ab2) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=KVM&page=1&pagesize=20&_=1428300970721
2015-04-06 11:46:07,673 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-12:ctx-a20f5ab2 ctx-7ec78f84) >>>Searching for hosts>>>
2015-04-06 11:46:07,682 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-12:ctx-a20f5ab2 ctx-7ec78f84) >>>Generating Response>>>
2015-04-06 11:46:07,688 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-a20f5ab2 ctx-7ec78f84) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=KVM&page=1&pagesize=20&_=1428300970721
2015-04-06 11:46:07,721 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-b03d3e34) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=XenServer&page=1&pagesize=20&_=1428300970763
2015-04-06 11:46:07,728 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-20:ctx-b03d3e34 ctx-d380c7bd) >>>Searching for hosts>>>
2015-04-06 11:46:07,731 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-20:ctx-b03d3e34 ctx-d380c7bd) >>>Generating Response>>>
2015-04-06 11:46:07,731 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-b03d3e34 ctx-d380c7bd) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=XenServer&page=1&pagesize=20&_=1428300970763
2015-04-06 11:46:07,737 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-89319aff) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=VMware&page=1&pagesize=20&_=1428300970797
2015-04-06 11:46:07,741 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-25:ctx-89319aff ctx-73b56a5a) >>>Searching for hosts>>>
2015-04-06 11:46:07,747 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-25:ctx-89319aff ctx-73b56a5a) >>>Generating Response>>>
2015-04-06 11:46:07,747 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-89319aff ctx-73b56a5a) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=VMware&page=1&pagesize=20&_=1428300970797
2015-04-06 11:46:07,782 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-83d8ef22) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=BareMetal&page=1&pagesize=20&_=1428300970833
2015-04-06 11:46:07,788 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-7:ctx-83d8ef22 ctx-32981648) >>>Searching for hosts>>>
2015-04-06 11:46:07,791 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-7:ctx-83d8ef22 ctx-32981648) >>>Generating Response>>>
2015-04-06 11:46:07,792 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-83d8ef22 ctx-32981648) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=BareMetal&page=1&pagesize=20&_=1428300970833
2015-04-06 11:46:07,814 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-b9923147) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Ovm&page=1&pagesize=20&_=1428300970867
2015-04-06 11:46:07,818 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-14:ctx-b9923147 ctx-5afbc283) >>>Searching for hosts>>>
2015-04-06 11:46:07,821 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-14:ctx-b9923147 ctx-5afbc283) >>>Generating Response>>>
2015-04-06 11:46:07,822 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-b9923147 ctx-5afbc283) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Ovm&page=1&pagesize=20&_=1428300970867
2015-04-06 11:46:07,826 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-d1f0badb) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=LXC&page=1&pagesize=20&_=1428300970886
2015-04-06 11:46:07,832 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-15:ctx-d1f0badb ctx-6b39c2b1) >>>Searching for hosts>>>
2015-04-06 11:46:07,835 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-15:ctx-d1f0badb ctx-6b39c2b1) >>>Generating Response>>>
2015-04-06 11:46:07,835 DEBUG [c.c.a.ApiServlet] (catalina-exec-15:ctx-d1f0badb ctx-6b39c2b1) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=LXC&page=1&pagesize=20&_=1428300970886
2015-04-06 11:46:09,641 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-151e9349) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=20&_=1428300972654
2015-04-06 11:46:09,649 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-8:ctx-151e9349 ctx-67b3304e) Received unknown parameters for command listHosts. Unknown parameters : listall
2015-04-06 11:46:09,649 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-8:ctx-151e9349 ctx-67b3304e) >>>Searching for hosts>>>
2015-04-06 11:46:09,659 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-8:ctx-151e9349 ctx-67b3304e) >>>Generating Response>>>
2015-04-06 11:46:09,668 DEBUG [c.c.a.ApiServlet] (catalina-exec-8:ctx-151e9349 ctx-67b3304e) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=20&_=1428300972654
2015-04-06 11:46:10,830 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-6418e206) ===START=== 172.21.8.92 -- GET command=listZones&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973841
2015-04-06 11:46:10,841 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-4:ctx-6418e206 ctx-47dc8d8b) Received unknown parameters for command listZones. Unknown parameters : listall
2015-04-06 11:46:10,854 DEBUG [c.c.a.ApiServlet] (catalina-exec-4:ctx-6418e206 ctx-47dc8d8b) ===END=== 172.21.8.92 -- GET command=listZones&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973841
2015-04-06 11:46:10,899 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-865bd7cb) ===START=== 172.21.8.92 -- GET command=listPods&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973953
2015-04-06 11:46:10,906 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-23:ctx-865bd7cb ctx-79766236) Received unknown parameters for command listPods. Unknown parameters : listall
2015-04-06 11:46:10,913 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-865bd7cb ctx-79766236) ===END=== 172.21.8.92 -- GET command=listPods&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973953
2015-04-06 11:46:10,967 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-04d8478a) ===START=== 172.21.8.92 -- GET command=listClusters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973997
2015-04-06 11:46:10,974 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-13:ctx-04d8478a ctx-b729e1fb) Received unknown parameters for command listClusters. Unknown parameters : listall
2015-04-06 11:46:10,984 DEBUG [c.c.a.ApiServlet] (catalina-exec-13:ctx-04d8478a ctx-b729e1fb) ===END=== 172.21.8.92 -- GET command=listClusters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300973997
2015-04-06 11:46:11,014 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-c10ba24f) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=1&_=1428300974066
2015-04-06 11:46:11,020 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-22:ctx-c10ba24f ctx-f6e725f1) Received unknown parameters for command listHosts. Unknown parameters : listall
2015-04-06 11:46:11,020 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-22:ctx-c10ba24f ctx-f6e725f1) >>>Searching for hosts>>>
2015-04-06 11:46:11,030 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-22:ctx-c10ba24f ctx-f6e725f1) >>>Generating Response>>>
2015-04-06 11:46:11,038 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-c10ba24f ctx-f6e725f1) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&listAll=true&page=1&pagesize=1&_=1428300974066
2015-04-06 11:46:11,085 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-bc98d1b2) ===START=== 172.21.8.92 -- GET command=listStoragePools&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974115
2015-04-06 11:46:11,092 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-21:ctx-bc98d1b2 ctx-48cf6044) Received unknown parameters for command listStoragePools. Unknown parameters : listall
2015-04-06 11:46:11,107 DEBUG [c.c.a.ApiServlet] (catalina-exec-21:ctx-bc98d1b2 ctx-48cf6044) ===END=== 172.21.8.92 -- GET command=listStoragePools&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974115
2015-04-06 11:46:11,170 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-7ea7a539) ===START=== 172.21.8.92 -- GET command=listImageStores&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=SecondaryStorage&listAll=true&page=1&pagesize=1&_=1428300974198
2015-04-06 11:46:11,176 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-1:ctx-7ea7a539 ctx-98bbfaa5) Received unknown parameters for command listImageStores. Unknown parameters : listall type
2015-04-06 11:46:11,188 DEBUG [c.c.a.ApiServlet] (catalina-exec-1:ctx-7ea7a539 ctx-98bbfaa5) ===END=== 172.21.8.92 -- GET command=listImageStores&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=SecondaryStorage&listAll=true&page=1&pagesize=1&_=1428300974198
2015-04-06 11:46:11,193 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-89fbf725) ===START=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974253
2015-04-06 11:46:11,200 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-16:ctx-89fbf725 ctx-5b3f58f2) Received unknown parameters for command listSystemVms. Unknown parameters : listall
2015-04-06 11:46:11,265 DEBUG [c.c.a.ApiServlet] (catalina-exec-16:ctx-89fbf725 ctx-5b3f58f2) ===END=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974253
2015-04-06 11:46:11,291 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-624b401c) ===START=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974345
2015-04-06 11:46:11,302 DEBUG [c.c.a.ApiServlet] (catalina-exec-11:ctx-624b401c ctx-189490f0) ===END=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=1&_=1428300974345
2015-04-06 11:46:11,327 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-4e9e5437) ===START=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&projectid=-1&page=1&pagesize=1&_=1428300974381
2015-04-06 11:46:11,338 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-4e9e5437 ctx-0bcc1ec4) ===END=== 172.21.8.92 -- GET command=listRouters&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&projectid=-1&page=1&pagesize=1&_=1428300974381
2015-04-06 11:46:11,343 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-3406c5c2) ===START=== 172.21.8.92 -- GET command=listCapacity&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300974402
2015-04-06 11:46:11,370 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-3406c5c2 ctx-46d93580) ===END=== 172.21.8.92 -- GET command=listCapacity&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300974402
2015-04-06 11:46:11,412 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-1c5e06a0) ===START=== 172.21.8.92 -- GET command=listHypervisors&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300974465
2015-04-06 11:46:11,421 DEBUG [c.c.a.ApiServlet] (catalina-exec-19:ctx-1c5e06a0 ctx-3ff321e6) ===END=== 172.21.8.92 -- GET command=listHypervisors&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&_=1428300974465
2015-04-06 11:46:11,426 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-9003a85c) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Hyperv&page=1&pagesize=20&_=1428300974485
2015-04-06 11:46:11,433 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-5:ctx-9003a85c ctx-6d460f54) >>>Searching for hosts>>>
2015-04-06 11:46:11,438 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-5:ctx-9003a85c ctx-6d460f54) >>>Generating Response>>>
2015-04-06 11:46:11,438 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-9003a85c ctx-6d460f54) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Hyperv&page=1&pagesize=20&_=1428300974485
2015-04-06 11:46:11,489 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-9dfe3cef) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=KVM&page=1&pagesize=20&_=1428300974518
2015-04-06 11:46:11,496 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-18:ctx-9dfe3cef ctx-16d8772b) >>>Searching for hosts>>>
2015-04-06 11:46:11,505 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-18:ctx-9dfe3cef ctx-16d8772b) >>>Generating Response>>>
2015-04-06 11:46:11,513 DEBUG [c.c.a.ApiServlet] (catalina-exec-18:ctx-9dfe3cef ctx-16d8772b) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=KVM&page=1&pagesize=20&_=1428300974518
2015-04-06 11:46:11,559 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-ecd1dc9c) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=XenServer&page=1&pagesize=20&_=1428300974595
2015-04-06 11:46:11,566 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-2:ctx-ecd1dc9c ctx-e1fd2c8e) >>>Searching for hosts>>>
2015-04-06 11:46:11,571 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-2:ctx-ecd1dc9c ctx-e1fd2c8e) >>>Generating Response>>>
2015-04-06 11:46:11,572 DEBUG [c.c.a.ApiServlet] (catalina-exec-2:ctx-ecd1dc9c ctx-e1fd2c8e) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=XenServer&page=1&pagesize=20&_=1428300974595
2015-04-06 11:46:11,577 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-a42a4ea9) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=VMware&page=1&pagesize=20&_=1428300974637
2015-04-06 11:46:11,583 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-9:ctx-a42a4ea9 ctx-63e183e6) >>>Searching for hosts>>>
2015-04-06 11:46:11,589 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-9:ctx-a42a4ea9 ctx-63e183e6) >>>Generating Response>>>
2015-04-06 11:46:11,589 DEBUG [c.c.a.ApiServlet] (catalina-exec-9:ctx-a42a4ea9 ctx-63e183e6) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=VMware&page=1&pagesize=20&_=1428300974637
2015-04-06 11:46:11,617 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-c437cdb9) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=BareMetal&page=1&pagesize=20&_=1428300974668
2015-04-06 11:46:11,625 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-17:ctx-c437cdb9 ctx-7e492b68) >>>Searching for hosts>>>
2015-04-06 11:46:11,631 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-17:ctx-c437cdb9 ctx-7e492b68) >>>Generating Response>>>
2015-04-06 11:46:11,632 DEBUG [c.c.a.ApiServlet] (catalina-exec-17:ctx-c437cdb9 ctx-7e492b68) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=BareMetal&page=1&pagesize=20&_=1428300974668
2015-04-06 11:46:11,683 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-6ce60245) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Ovm&page=1&pagesize=20&_=1428300974715
2015-04-06 11:46:11,690 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-12:ctx-6ce60245 ctx-1f76fc57) >>>Searching for hosts>>>
2015-04-06 11:46:11,695 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-12:ctx-6ce60245 ctx-1f76fc57) >>>Generating Response>>>
2015-04-06 11:46:11,695 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-6ce60245 ctx-1f76fc57) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=Ovm&page=1&pagesize=20&_=1428300974715
2015-04-06 11:46:11,724 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-8775ccfc) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=LXC&page=1&pagesize=20&_=1428300974779
2015-04-06 11:46:11,731 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-20:ctx-8775ccfc ctx-e8b81160) >>>Searching for hosts>>>
2015-04-06 11:46:11,736 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-20:ctx-8775ccfc ctx-e8b81160) >>>Generating Response>>>
2015-04-06 11:46:11,736 DEBUG [c.c.a.ApiServlet] (catalina-exec-20:ctx-8775ccfc ctx-e8b81160) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&type=routing&hypervisor=LXC&page=1&pagesize=20&_=1428300974779
2015-04-06 11:46:12,343 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-1fcede57) ===START=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=20&_=1428300975384
2015-04-06 11:46:12,350 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-25:ctx-1fcede57 ctx-4e47d58e) Received unknown parameters for command listSystemVms. Unknown parameters : listall
2015-04-06 11:46:12,370 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) Ping from 1
2015-04-06 11:46:12,370 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-11:null) Process host VM state report from ping process. host: 1
2015-04-06 11:46:12,374 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-11:null) Process VM state report. host: 1, number of records in report: 1
2015-04-06 11:46:12,376 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-11:null) VM state report. host: 1, vm id: 2, power state: PowerOn
2015-04-06 11:46:12,383 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-11:null) VM power state does not change, skip DB writing. vm id: 2
2015-04-06 11:46:12,388 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-11:null) Done with process of VM state report. host: 1
2015-04-06 11:46:12,508 DEBUG [c.c.a.ApiServlet] (catalina-exec-25:ctx-1fcede57 ctx-4e47d58e) ===END=== 172.21.8.92 -- GET command=listSystemVms&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&page=1&pagesize=20&_=1428300975384
2015-04-06 11:46:12,523 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-63569b67) ===START=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&details=min&_=1428300975578
2015-04-06 11:46:12,530 WARN [c.c.a.d.ParamGenericValidationWorker] (catalina-exec-7:ctx-63569b67 ctx-48930f97) Received unknown parameters for command listHosts. Unknown parameters : listall
2015-04-06 11:46:12,530 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-7:ctx-63569b67 ctx-48930f97) >>>Searching for hosts>>>
2015-04-06 11:46:12,540 DEBUG [c.c.a.q.QueryManagerImpl] (catalina-exec-7:ctx-63569b67 ctx-48930f97) >>>Generating Response>>>
2015-04-06 11:46:12,549 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-63569b67 ctx-48930f97) ===END=== 172.21.8.92 -- GET command=listHosts&response=json&sessionkey=N5fFlwFTk%2Fn3cUCDmv9MMOEJhCw%3D&listAll=true&details=min&_=1428300975578
2015-04-06 11:46:14,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 2-43547: Processing Seq 2-43547: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-06 11:46:14,778 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 2-43547: Sending Seq 2-43547: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-06 11:46:24,773 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-43548: Processing Seq 2-43548: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-06 11:46:24,778 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-43548: Sending Seq 2-43548: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-06 11:46:29,772 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-43549: Processing Seq 2-43549: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-06 11:46:29,775 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-43549: Sending Seq 2-43549: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-04-06 11:46:30,460 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 2
2015-04-06 11:46:31,850 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d4f9c0f7) Found 0 routers to update status.
2015-04-06 11:46:31,853 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-d4f9c0f7) Found 0 networks to update RvR status.
2015-04-06 11:46:34,528 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-ba131830) HostStatsCollector is running...
2015-04-06 11:46:35,126 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-ba131830) Seq 1-6592706904517007134: Received: { Ans: , MgmtId: 345050277750, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-04-06 11:46:35,570 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) Zone 1 is ready to launch secondary storage VM
2015-04-06 11:46:35,579 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) No running secondary storage vms found in datacenter id=1, starting one
2015-04-06 11:46:35,589 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) Found a stopped secondary storage vm, bring it up to running pool. secStorageVm vm id : 5589
2015-04-06 11:46:35,603 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-8e5aacc2) Sync job-16796 execution on object VmWorkJobQueue.5589
2015-04-06 11:46:35,607 WARN [c.c.u.d.Merovingian2] (secstorage-1:ctx-8e5aacc2) Was unable to find lock for the key vm_instance5589 and thread id 1101220913
2015-04-06 11:46:35,922 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-2ed24b3f) Execute sync-queue item: SyncQueueItemVO {id:16766, queueId: 16765, contentType: AsyncJob, contentId: 16796, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon Apr 06 11:46:35 IST 2015}
2015-04-06 11:46:35,926 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-2ed24b3f) Schedule queued job-16796
2015-04-06 11:46:35,933 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Add job-16796 into job monitoring
2015-04-06 11:46:35,934 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Executing AsyncJobVO {id:16796, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAV1XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 06 11:46:35 IST 2015}
2015-04-06 11:46:35,934 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Run VM work job: com.cloud.vm.VmWorkStart for VM 5589, job origin: 1
2015-04-06 11:46:35,937 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":5589,"handlerName":"VirtualMachineManagerImpl"}
2015-04-06 11:46:35,953 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-e14d154e) Zone 1 is ready to launch console proxy
2015-04-06 11:46:35,961 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
2015-04-06 11:46:35,961 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Successfully transitioned to start state for VM[SecondaryStorageVm|s-5589-VM] reservation id = cc0e8e23-42f0-40ff-8e73-f6f7122db893
2015-04-06 11:46:35,965 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Trying to deploy VM, vm has dcId: 1 and podId: 1
2015-04-06 11:46:35,965 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Deploy avoids pods: null, clusters: null, hosts: null
2015-04-06 11:46:35,973 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Deploy avoids pods: null, clusters: null, hosts: null
2015-04-06 11:46:35,974 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5977abd5
2015-04-06 11:46:35,974 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2015-04-06 11:46:35,975 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Is ROOT volume READY (pool already allocated)?: No
2015-04-06 11:46:35,975 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Searching resources only under specified Pod: 1
2015-04-06 11:46:35,975 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
2015-04-06 11:46:35,991 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking resources in Cluster: 1 under Pod: 1
2015-04-06 11:46:35,991 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2015-04-06 11:46:35,996 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
2015-04-06 11:46:36,003 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
2015-04-06 11:46:36,003 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2015-04-06 11:46:36,014 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:8, speed:2666) to support requested CPU: 1 and requested speed: 500
2015-04-06 11:46:36,014 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
2015-04-06 11:46:36,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-06 11:46:36,018 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Free CPU: 20828 , Requested CPU: 500
2015-04-06 11:46:36,019 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Free RAM: 19884453888 , Requested RAM: 536870912
2015-04-06 11:46:36,019 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-04-06 11:46:36,019 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 21328, total with overprovisioning: 21328; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-06 11:46:36,019 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1073741824, reserved: 0, total: 20958195712; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-04-06 11:46:36,019 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2015-04-06 11:46:36,019 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
2015-04-06 11:46:36,022 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking suitable pools for volume (Id, Type): (5589,ROOT)
2015-04-06 11:46:36,022 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) We need to allocate new storagepool for this volume
2015-04-06 11:46:36,024 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Calling StoragePoolAllocators to find suitable pools
2015-04-06 11:46:36,026 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) LocalStoragePoolAllocator trying to find storage pool to fit the vm
2015-04-06 11:46:36,026 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) ClusterScopeStoragePoolAllocator looking for storage pool
2015-04-06 11:46:36,026 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Looking for pools in dc: 1 pod:1 cluster:1
2015-04-06 11:46:36,028 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Found pools matching tags: [Pool[1|NetworkFilesystem]]
2015-04-06 11:46:36,031 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Removing pool Pool[1|NetworkFilesystem] from avoid set, must have been inserted when searching for another disk's tag
2015-04-06 11:46:36,033 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking if storage pool is suitable, name: null ,poolId: 1
2015-04-06 11:46:36,038 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking pool 1 for storage, totalSize: 365524156416, usedBytes: 1115684864, usedPct: 0.003052287637948197, disable threshold: 0.85
2015-04-06 11:46:36,045 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Found storage pool primary of type NetworkFilesystem with overprovisioning factor 2
2015-04-06 11:46:36,045 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Total over provisioned capacity calculated is 2 * 365524156416
2015-04-06 11:46:36,046 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Total capacity of the pool primary id: 1 is 731048312832
2015-04-06 11:46:36,047 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking pool: 1 for volume allocation [Vol[5589|vm=5589|ROOT]], maxSize : 731048312832, totalAllocatedSize : 0, askingSize : 307120640, allocated disable threshold: 0.85
2015-04-06 11:46:36,047 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
2015-04-06 11:46:36,048 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
2015-04-06 11:46:36,048 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Checking if host: 1 can access any suitable storage pool for volume: ROOT
2015-04-06 11:46:36,049 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Host: 1 can access pool: 1
2015-04-06 11:46:36,050 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Found a potential host id: 1 name: ctkvm1 and associated storage pools for this VM
2015-04-06 11:46:36,051 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) 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(1)-Storage(Volume(5589|ROOT-->Pool(1))]
2015-04-06 11:46:36,051 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Deployment found - P0=VM[SecondaryStorageVm|s-5589-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(5589|ROOT-->Pool(1))]
2015-04-06 11:46:36,059 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) We are allocating VM, increasing the used capacity of this host:1
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Current Used CPU: 500 , Free CPU:20828 ,Requested CPU: 500
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Current Used RAM: 1073741824 , Free RAM:19884453888 ,Requested RAM: 536870912
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
2015-04-06 11:46:36,065 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) RAM STATS after allocation: for host: 1, old used: 1073741824, old reserved: 0, total: 20958195712; new used: 1610612736, reserved: 0; requested mem: 536870912,alloc_from_last:false
2015-04-06 11:46:36,067 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) VM is being created in podId: 1
2015-04-06 11:46:36,070 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Network id=200 is already implemented
2015-04-06 11:46:36,084 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Network id=202 is already implemented
2015-04-06 11:46:36,099 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Network id=201 is already implemented
2015-04-06 11:46:36,112 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Allocated a nic NicProfile[22354-5589-cc0e8e23-42f0-40ff-8e73-f6f7122db893-10.204.207.170-null for VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:36,117 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Network id=203 is already implemented
2015-04-06 11:46:36,129 DEBUG [c.c.u.d.T.Transaction] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Rolling back the transaction: Time = 0 Name = Work-Job-Executor-166; called by -TransactionLegacy.rollback:900-DataCenterIpAddressDaoImpl.takeIpAddress:61-GeneratedMethodAccessor253.invoke:-1-DelegatingMethodAccessorImpl.invoke:43-Method.invoke:606-AopUtils.invokeJoinpointUsingReflection:317-ReflectiveMethodInvocation.invokeJoinpoint:183-ReflectiveMethodInvocation.proceed:150-TransactionContextInterceptor.invoke:34-ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.invoke:91-ReflectiveMethodInvocation.proceed:172
2015-04-06 11:46:36,130 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Insufficient capacity
com.cloud.exception.InsufficientAddressCapacityException: Unable to get a management ip addressScope=interface com.cloud.dc.Pod; id=1
at com.cloud.network.guru.PodBasedNetworkGuru.reserve(PodBasedNetworkGuru.java:123)
at com.cloud.network.guru.StorageNetworkGuru.reserve(StorageNetworkGuru.java:122)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1308)
at org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1279)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:986)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor281.invoke(Unknown Source)
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-04-06 11:46:36,132 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Cleaning up resources for the vm VM[SecondaryStorageVm|s-5589-VM] in Starting state
2015-04-06 11:46:36,134 DEBUG [c.c.a.t.Request] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Seq 1-6592706904517007135: Sending { Cmd , MgmtId: 345050277750, via: 1(ctkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"s-5589-VM","wait":0}}] }
2015-04-06 11:46:36,366 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) Seq 1-6592706904517007135: Processing: { Ans: , MgmtId: 345050277750, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
2015-04-06 11:46:36,367 DEBUG [c.c.a.t.Request] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Seq 1-6592706904517007135: Received: { Ans: , MgmtId: 345050277750, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2015-04-06 11:46:36,380 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Released nic: NicProfile[22353-5589-null-null-null
2015-04-06 11:46:36,391 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Releasing ip address for reservationId=cc0e8e23-42f0-40ff-8e73-f6f7122db893, instance=22354
2015-04-06 11:46:36,391 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Released nic: NicProfile[22354-5589-null-null-null
2015-04-06 11:46:36,404 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Releasing ip address for reservationId=cc0e8e23-42f0-40ff-8e73-f6f7122db893, instance=22355
2015-04-06 11:46:36,404 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Released nic: NicProfile[22355-5589-null-null-null
2015-04-06 11:46:36,408 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Successfully released network resources for the vm VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:36,408 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-5589-VM] in Starting state
2015-04-06 11:46:36,413 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Deploy avoids pods: [1], clusters: null, hosts: [1]
2015-04-06 11:46:36,414 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5977abd5
2015-04-06 11:46:36,414 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
2015-04-06 11:46:36,414 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Is ROOT volume READY (pool already allocated)?: No
2015-04-06 11:46:36,415 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Searching resources only under specified Pod: 1
2015-04-06 11:46:36,415 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) The specified pod is in avoid set, returning.
2015-04-06 11:46:36,426 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2015-04-06 11:46:36,435 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Hosts's actual total CPU: 21328 and CPU after applying overprovisioning: 21328
2015-04-06 11:46:36,435 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Hosts's actual total RAM: 20958195712 and RAM after applying overprovisioning: 20958195712
2015-04-06 11:46:36,435 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 21328, total with overprovisioning: 21328; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-06 11:46:36,435 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) release mem from host: 1, old used: 1610612736,reserved: 0, total: 20958195712; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-04-06 11:46:36,438 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-06 11:46:36,438 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796 ctx-86e7d3d8) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-04-06 11:46:36,439 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 5589, job origin: 1
2015-04-06 11:46:36,439 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Unable to complete AsyncJobVO {id:16796, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAV1XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 06 11:46:35 IST 2015}, job origin:1
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-5589-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.GeneratedMethodAccessor281.invoke(Unknown Source)
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-04-06 11:46:36,442 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Complete async job-16796, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAXkpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bU2Vjb25kYXJ5U3RvcmFnZVZtfHMtNTU4OS1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6XQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-04-06 11:46:36,454 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Done executing com.cloud.vm.VmWorkStart for job-16796
2015-04-06 11:46:36,465 WARN [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) Exception while trying to start secondary storage vm
java.lang.RuntimeException: Job failed due to exception Unable to create a deployment for VM[SecondaryStorageVm|s-5589-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-04-06 11:46:36,472 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 5589, will recycle it and start a new one
2015-04-06 11:46:36,473 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Sync queue (16765) is currently empty
2015-04-06 11:46:36,477 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-166:ctx-a93c6bcf job-1/job-16796) Remove job-16796 from job monitoring
2015-04-06 11:46:36,486 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-8e5aacc2) Sync job-16797 execution on object VmWorkJobQueue.5589
2015-04-06 11:46:36,489 WARN [c.c.u.d.Merovingian2] (secstorage-1:ctx-8e5aacc2) Was unable to find lock for the key vm_instance5589 and thread id 1101220913
2015-04-06 11:46:37,922 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-76c081d3) Execute sync-queue item: SyncQueueItemVO {id:16767, queueId: 16765, contentType: AsyncJob, contentId: 16797, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon Apr 06 11:46:36 IST 2015}
2015-04-06 11:46:37,924 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-76c081d3) Schedule queued job-16797
2015-04-06 11:46:37,927 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Add job-16797 into job monitoring
2015-04-06 11:46:37,927 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Executing AsyncJobVO {id:16797, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAV1XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050277750, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon Apr 06 11:46:36 IST 2015}
2015-04-06 11:46:37,928 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Run VM work job: com.cloud.vm.VmWorkStop for VM 5589, job origin: 1
2015-04-06 11:46:37,930 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797 ctx-2979ec82) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":5589,"handlerName":"VirtualMachineManagerImpl"}
2015-04-06 11:46:37,940 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797 ctx-2979ec82) VM is already stopped: VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:37,940 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797 ctx-2979ec82) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":5589,"handlerName":"VirtualMachineManagerImpl"}
2015-04-06 11:46:37,941 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797 ctx-2979ec82) Complete async job-16797, jobStatus: SUCCEEDED, resultCode: 0, result: null
2015-04-06 11:46:37,952 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 5589, job origin: 1
2015-04-06 11:46:37,953 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Done executing com.cloud.vm.VmWorkStop for job-16797
2015-04-06 11:46:37,974 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Sync queue (16765) is currently empty
2015-04-06 11:46:37,975 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-1:ctx-fd9a93c4 job-1/job-16797) Remove job-16797 from job monitoring
2015-04-06 11:46:37,977 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx-8e5aacc2) VM state transitted from :Stopped to Expunging with event: ExpungeOperationvm's original host id: null new host id: null host id before state transition: null
2015-04-06 11:46:37,979 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-8e5aacc2) Destroying vm VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:37,979 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-8e5aacc2) Cleaning up NICS
2015-04-06 11:46:37,979 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Cleaning network for vm: 5589
2015-04-06 11:46:37,994 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-8e5aacc2) public network deallocate network: networkId: 200, ip: 10.204.207.161
2015-04-06 11:46:38,003 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-8e5aacc2) Deallocated nic: NicProfile[22352-5589-null-null-null
2015-04-06 11:46:38,006 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Removed nic id=22352
2015-04-06 11:46:38,008 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Revoving nic secondary ip entry ...
2015-04-06 11:46:38,015 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Removed nic id=22353
2015-04-06 11:46:38,017 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Revoving nic secondary ip entry ...
2015-04-06 11:46:38,032 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Removed nic id=22354
2015-04-06 11:46:38,033 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Revoving nic secondary ip entry ...
2015-04-06 11:46:38,045 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-a3a158bd) AutoScaling Monitor is running...
2015-04-06 11:46:38,050 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Removed nic id=22355
2015-04-06 11:46:38,051 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-8e5aacc2) Revoving nic secondary ip entry ...
2015-04-06 11:46:38,052 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-8e5aacc2) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage
2015-04-06 11:46:38,052 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:ctx-8e5aacc2) Cleaning storage for vm: 5589
2015-04-06 11:46:38,063 INFO [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:ctx-8e5aacc2) Expunge volume with no data store specified
2015-04-06 11:46:38,065 INFO [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:ctx-8e5aacc2) Volume 5589 is not referred anywhere, remove it from volumes table
2015-04-06 11:46:38,071 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-8e5aacc2) Expunged VM[SecondaryStorageVm|s-5589-VM]
2015-04-06 11:46:38,074 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-8e5aacc2) Primary secondary storage is not even started, wait until next turn
2015-04-06 11:46:39,774 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 2-43551: Processing Seq 2-43551: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-04-06 11:46:39,779 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) SeqA 2-43551: Sending Seq 2-43551: { Ans: , MgmtId: 345050277750, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
^C
> After restarting KVm
> --------------------
>
> Key: CLOUDSTACK-8359
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8359
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: KVM
> Affects Versions: 4.4.2
> Reporter: Nagaraju
>
> After rebooting the KVM hypervisor ,SSVM got stopped ,need help in resolving the issue.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)