cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Wei Zhou (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CLOUDSTACK-8454) Unable to start Secondary Storage VMs
Date Mon, 11 May 2015 08:02:00 GMT

    [ https://issues.apache.org/jira/browse/CLOUDSTACK-8454?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14537698#comment-14537698 ] 

Wei Zhou commented on CLOUDSTACK-8454:
--------------------------------------

the error message is:
Unable to add port vnet4 to OVS bridge cloudbr0: Operation not permitted

please check your configuration.



> Unable to start Secondary Storage VMs
> -------------------------------------
>
>                 Key: CLOUDSTACK-8454
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8454
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>            Reporter: Nagaraju
>
> HI 
> I'm getting the below error message ,and unable to start SSVM,
> 2015-05-11 13:03:11,126 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
> 2015-05-11 13:03:11,126 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b FirstFitRoutingAllocator) Host name: cstkvm1, hostId: 1 is in avoid set, skipping this and trying other available hosts
> 2015-05-11 13:03:11,126 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
> 2015-05-11 13:03:11,126 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) No suitable hosts found
> 2015-05-11 13:03:11,126 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) No suitable hosts found under this Cluster: 1
> 2015-05-11 13:03:11,127 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
> 2015-05-11 13:03:11,127 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Searching resources only under specified Cluster: 1
> 2015-05-11 13:03:11,128 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) The specified cluster is in avoid set, returning.
> 2015-05-11 13:03:11,129 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Deploy avoids pods: null, clusters: [1], hosts: [1]
> 2015-05-11 13:03:11,130 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@eb6d585
> 2015-05-11 13:03:11,130 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 500, requested ram: 536870912
> 2015-05-11 13:03:11,130 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Is ROOT volume READY (pool already allocated)?: No
> 2015-05-11 13:03:11,130 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Searching resources only under specified Pod: 1
> 2015-05-11 13:03:11,130 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1
> 2015-05-11 13:03:11,133 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Removing from the clusterId list these clusters from avoid set: [1]
> 2015-05-11 13:03:11,133 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) No clusters found after removing disabled clusters and clusters in avoid list, returning.
> 2015-05-11 13:03:11,162 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) 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-05-11 13:03:11,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
> 2015-05-11 13:03:11,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Hosts's actual total RAM: 270766170112 and RAM after applying overprovisioning: 270766178304
> 2015-05-11 13:03:11,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2015-05-11 13:03:11,166 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) release mem from host: 1, old used: 1610612736,reserved: 0, total: 270766178304; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2015-05-11 13:03:11,168 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-26-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> 2015-05-11 13:03:11,169 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111 ctx-f33fe85b) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-26-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> 2015-05-11 13:03:11,169 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 26, job origin: 4
> 2015-05-11 13:03:11,169 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Unable to complete AsyncJobVO {id:111, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAGnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon May 11 13:03:10 IST 2015}, job origin:4
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-26-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:5201)
>         at sun.reflect.GeneratedMethodAccessor227.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:5346)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
>         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:459)
>         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-05-11 13:03:11,170 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Complete async job-111, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAXEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bU2Vjb25kYXJ5U3RvcmFnZVZtfHMtMjYtVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH2dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHLcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
> 2015-05-11 13:03:11,174 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Done executing com.cloud.vm.VmWorkStart for job-111
> 2015-05-11 13:03:11,181 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Sync queue (74) is currently empty
> 2015-05-11 13:03:11,181 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-43:ctx-d0a1b1c6 job-4/job-111) Remove job-111 from job monitoring
> 2015-05-11 13:03:11,183 WARN  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-b8a7f302) 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-26-VM]
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
>         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:459)
>         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-05-11 13:03:11,184 INFO  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-b8a7f302) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 26, will recycle it and start a new one
> 2015-05-11 13:03:11,192 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-b8a7f302) Sync job-112 execution on object VmWorkJobQueue.26
> 2015-05-11 13:03:11,194 WARN  [c.c.u.d.Merovingian2] (secstorage-1:ctx-b8a7f302) Was unable to find lock for the key vm_instance26 and thread id 1106635406
> 2015-05-11 13:03:12,484 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-b72d7f47) Execute sync-queue item: SyncQueueItemVO {id:44, queueId: 74, contentType: AsyncJob, contentId: 112, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon May 11 13:03:11 IST 2015}
> 2015-05-11 13:03:12,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-b72d7f47) Schedule queued job-112
> 2015-05-11 13:03:12,488 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Add job-112 into job monitoring
> 2015-05-11 13:03:12,489 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Executing AsyncJobVO {id:112, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStop, cmdInfo: rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAGnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon May 11 13:03:11 IST 2015}
> 2015-05-11 13:03:12,489 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Run VM work job: com.cloud.vm.VmWorkStop for VM 26, job origin: 4
> 2015-05-11 13:03:12,490 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112 ctx-768d3397) Execute VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":26,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-11 13:03:12,493 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112 ctx-768d3397) VM is already stopped: VM[SecondaryStorageVm|s-26-VM]
> 2015-05-11 13:03:12,494 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112 ctx-768d3397) Done executing VM work job: com.cloud.vm.VmWorkStop{"cleanup":false,"userId":1,"accountId":1,"vmId":26,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-11 13:03:12,494 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112 ctx-768d3397) Complete async job-112, jobStatus: SUCCEEDED, resultCode: 0, result: null
> 2015-05-11 13:03:12,498 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Done with run of VM work job: com.cloud.vm.VmWorkStop for VM 26, job origin: 4
> 2015-05-11 13:03:12,499 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Done executing com.cloud.vm.VmWorkStop for job-112
> 2015-05-11 13:03:12,505 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Sync queue (74) is currently empty
> 2015-05-11 13:03:12,505 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-44:ctx-ea4e7502 job-4/job-112) Remove job-112 from job monitoring
> 2015-05-11 13:03:12,509 DEBUG [c.c.c.CapacityManagerImpl] (secstorage-1:ctx-b8a7f302) 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-05-11 13:03:12,509 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-b8a7f302) Destroying vm VM[SecondaryStorageVm|s-26-VM]
> 2015-05-11 13:03:12,509 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-b8a7f302) Cleaning up NICS
> 2015-05-11 13:03:12,510 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Cleaning network for vm: 26
> 2015-05-11 13:03:12,517 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-b8a7f302) public network deallocate network: networkId: 200, ip: 10.204.195.2
> 2015-05-11 13:03:12,522 DEBUG [c.c.n.g.PublicNetworkGuru] (secstorage-1:ctx-b8a7f302) Deallocated nic: NicProfile[100-26-null-null-null
> 2015-05-11 13:03:12,523 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Removed nic id=100
> 2015-05-11 13:03:12,524 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Revoving nic secondary ip entry ...
> 2015-05-11 13:03:12,528 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Removed nic id=101
> 2015-05-11 13:03:12,529 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Revoving nic secondary ip entry ...
> 2015-05-11 13:03:12,539 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Removed nic id=102
> 2015-05-11 13:03:12,539 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Revoving nic secondary ip entry ...
> 2015-05-11 13:03:12,547 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Removed nic id=103
> 2015-05-11 13:03:12,548 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-b8a7f302) Revoving nic secondary ip entry ...
> 2015-05-11 13:03:12,548 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-b8a7f302) Cleaning up hypervisor data structures (ex. SRs in XenServer) for managed storage
> 2015-05-11 13:03:12,548 DEBUG [o.a.c.e.o.VolumeOrchestrator] (secstorage-1:ctx-b8a7f302) Cleaning storage for vm: 26
> 2015-05-11 13:03:12,568 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-b8a7f302) Seq 1-4664884789025702013: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"13b9b44e-d3af-482c-bb66-196fe3c84ffd","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2cde1151-a6ca-472c-88a4-6af6175d31ba","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=2cde1151-a6ca-472c-88a4-6af6175d31ba"}},"name":"ROOT-26","size":0,"path":"13b9b44e-d3af-482c-bb66-196fe3c84ffd","volumeId":26,"vmName":"s-26-VM","accountId":1,"format":"QCOW2","id":26,"deviceId":0,"hypervisorType":"KVM"}},"wait":0}}] }
> 2015-05-11 13:03:12,579 DEBUG [c.c.a.t.Request] (AgentManager-Handler-5:null) Seq 1-4664884789025702013: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:12,579 DEBUG [c.c.a.t.Request] (secstorage-1:ctx-b8a7f302) Seq 1-4664884789025702013: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { Answer } }
> 2015-05-11 13:03:12,586 INFO  [o.a.c.s.v.VolumeServiceImpl] (secstorage-1:ctx-b8a7f302) Volume 26 is not referred anywhere, remove it from volumes table
> 2015-05-11 13:03:12,594 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-b8a7f302) Expunged VM[SecondaryStorageVm|s-26-VM]
> 2015-05-11 13:03:12,597 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-b8a7f302) Primary secondary storage is not even started, wait until next turn
> 2015-05-11 13:03:14,838 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-268: Processing Seq 2-268:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:14,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 2-268: Sending Seq 2-268:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:19,839 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-269: Processing Seq 2-269:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:19,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-8:null) SeqA 2-269: Sending Seq 2-269:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:22,482 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:ctx-215cc30c) Found 0 running routers. 
> 2015-05-11 13:03:22,484 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-5edeed6b) Found 0 routers to update status. 
> 2015-05-11 13:03:22,485 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:ctx-5edeed6b) Found 0 networks to update RvR status. 
> 2015-05-11 13:03:22,497 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl] (ExternalNetworkMonitor-1:ctx-06953a3b) External devices stats collector is running...
> 2015-05-11 13:03:22,682 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-93c53f1f) Snapshot scheduler.poll is being called at 2015-05-11 07:33:22 GMT
> 2015-05-11 13:03:22,683 DEBUG [c.c.s.s.SnapshotSchedulerImpl] (SnapshotPollTask:ctx-93c53f1f) Got 0 snapshots to be executed at 2015-05-11 07:33:22 GMT
> 2015-05-11 13:03:23,420 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-7:null) Ping from 2
> 2015-05-11 13:03:24,839 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-271: Processing Seq 2-271:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:24,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-271: Sending Seq 2-271:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:27,538 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Resetting hosts suitable for reconnect
> 2015-05-11 13:03:27,539 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Completed resetting hosts suitable for reconnect
> 2015-05-11 13:03:27,539 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Acquiring hosts for clusters already owned by this management server
> 2015-05-11 13:03:27,540 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Completed acquiring hosts for clusters already owned by this management server
> 2015-05-11 13:03:27,540 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Acquiring hosts for clusters not owned by any management server
> 2015-05-11 13:03:27,540 DEBUG [c.c.h.d.HostDaoImpl] (ClusteredAgentManager Timer:ctx-3b2bac8a) Completed acquiring hosts for clusters not owned by any management server
> 2015-05-11 13:03:27,688 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-04e99f4e) Expunge completed work job-110
> 2015-05-11 13:03:27,691 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-04e99f4e) Expunge completed work job-111
> 2015-05-11 13:03:27,693 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-04e99f4e) Expunge completed work job-112
> 2015-05-11 13:03:34,841 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-272: Processing Seq 2-272:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:34,844 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 2-272: Sending Seq 2-272:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:35,283 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-9:null) Ping from 1
> 2015-05-11 13:03:35,284 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-9:null) Process host VM state report from ping process. host: 1
> 2015-05-11 13:03:35,287 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-9:null) Process VM state report. host: 1, number of records in report: 1
> 2015-05-11 13:03:35,287 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-9:null) VM state report. host: 1, vm id: 1, power state: PowerOn
> 2015-05-11 13:03:35,289 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-9:null) VM power state does not change, skip DB writing. vm id: 1
> 2015-05-11 13:03:35,291 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentManager-Handler-9:null) Done with process of VM state report. host: 1
> 2015-05-11 13:03:37,689 DEBUG [c.c.s.StatsCollector] (StatsCollector-4:ctx-723084c0) AutoScaling Monitor is running...
> 2015-05-11 13:03:37,696 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-2da2493d) VmStatsCollector is running...
> 2015-05-11 13:03:38,521 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-0ab724c6) StorageCollector is running...
> 2015-05-11 13:03:38,526 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-0ab724c6) There is no secondary storage VM for secondary storage host secondary
> 2015-05-11 13:03:38,529 INFO  [c.c.a.t.Request] (StatsCollector-3:ctx-0ab724c6) not building log message for '[{}]', _cmds.length == 1
> 2015-05-11 13:03:38,576 INFO  [c.c.a.t.Request] (AgentManager-Handler-12:null) not building log message for '[{}]', _cmds.length == 1
> 2015-05-11 13:03:38,577 DEBUG [c.c.a.t.Request] (StatsCollector-3:ctx-0ab724c6) Seq 1-4664884789025702014: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
> 2015-05-11 13:03:39,677 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-4bba785f) Zone 1 is ready to launch console proxy
> 2015-05-11 13:03:39,842 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 2-273: Processing Seq 2-273:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:39,845 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) SeqA 2-273: Sending Seq 2-273:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:40,007 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) Zone 1 is ready to launch secondary storage VM
> 2015-05-11 13:03:40,011 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) No running secondary storage vms found in datacenter id=1, starting one
> 2015-05-11 13:03:40,015 INFO  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) No stopped secondary storage vm is available, need to allocate a new secondary storage vm
> 2015-05-11 13:03:40,016 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) Assign secondary storage vm from a newly started instance for request from data center : 1
> 2015-05-11 13:03:40,025 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Found existing network configuration for offering [Network Offering [1-Public-System-Public-Network]: Ntwk[97575f7f-3f92-4e33-bcca-ffdd065f5c61|Public|1]
> 2015-05-11 13:03:40,025 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
> 2015-05-11 13:03:40,028 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Found existing network configuration for offering [Network Offering [3-Control-System-Control-Network]: Ntwk[c84ea23e-f71d-44d4-ae93-4444a39f156d|Control|3]
> 2015-05-11 13:03:40,028 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
> 2015-05-11 13:03:40,031 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Found existing network configuration for offering [Network Offering [2-Management-System-Management-Network]: Ntwk[484970d9-da8e-48fb-a369-084d2ec5d565|Management|2]
> 2015-05-11 13:03:40,031 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
> 2015-05-11 13:03:40,033 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Found existing network configuration for offering [Network Offering [4-Storage-System-Storage-Network]: Ntwk[b3b94e14-df17-4726-8baa-bd40ca63b269|Storage|4]
> 2015-05-11 13:03:40,034 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Releasing lock for Acct[3ac1bb7a-f407-11e4-8193-005056997f17-system]
> 2015-05-11 13:03:40,045 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-febdd7c0) Allocating entries for VM: VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,047 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-febdd7c0) Allocating nics for VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,048 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Allocating nic for vm VM[SecondaryStorageVm|s-27-VM] in network Ntwk[97575f7f-3f92-4e33-bcca-ffdd065f5c61|Public|1] with requested profile NicProfile[0-0-null-null-null
> 2015-05-11 13:03:40,059 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Allocating nic for vm VM[SecondaryStorageVm|s-27-VM] in network Ntwk[c84ea23e-f71d-44d4-ae93-4444a39f156d|Control|3] with requested profile null
> 2015-05-11 13:03:40,063 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Allocating nic for vm VM[SecondaryStorageVm|s-27-VM] in network Ntwk[484970d9-da8e-48fb-a369-084d2ec5d565|Management|2] with requested profile null
> 2015-05-11 13:03:40,070 DEBUG [o.a.c.e.o.NetworkOrchestrator] (secstorage-1:ctx-febdd7c0) Allocating nic for vm VM[SecondaryStorageVm|s-27-VM] in network Ntwk[b3b94e14-df17-4726-8baa-bd40ca63b269|Storage|4] with requested profile null
> 2015-05-11 13:03:40,075 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-febdd7c0) Allocating disks for VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,080 DEBUG [c.c.v.VirtualMachineManagerImpl] (secstorage-1:ctx-febdd7c0) Allocation completed for VM: VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,082 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-febdd7c0) received secondary storage vm alert
> 2015-05-11 13:03:40,083 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-febdd7c0) New secondary storage vm created, zone: Zone1, secStorageVm: s-27-VM, public IP: null, private IP: null
> 2015-05-11 13:03:40,091 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (secstorage-1:ctx-febdd7c0) Sync job-113 execution on object VmWorkJobQueue.27
> 2015-05-11 13:03:40,096 WARN  [c.c.u.d.Merovingian2] (secstorage-1:ctx-febdd7c0) Was unable to find lock for the key vm_instance27 and thread id 1106635406
> 2015-05-11 13:03:40,484 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-4cb98615) Execute sync-queue item: SyncQueueItemVO {id:45, queueId: 77, contentType: AsyncJob, contentId: 113, lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null, created: Mon May 11 13:03:40 IST 2015}
> 2015-05-11 13:03:40,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-4cb98615) Schedule queued job-113
> 2015-05-11 13:03:40,488 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Add job-113 into job monitoring
> 2015-05-11 13:03:40,488 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Executing AsyncJobVO {id:113, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon May 11 13:03:40 IST 2015}
> 2015-05-11 13:03:40,489 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Run VM work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 4
> 2015-05-11 13:03:40,490 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":27,"handlerName":"VirtualMachineManagerImpl"}
> 2015-05-11 13:03:40,496 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) 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-05-11 13:03:40,496 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Successfully transitioned to start state for VM[SecondaryStorageVm|s-27-VM] reservation id = ef7c249f-d533-4f39-b992-41efcbdfae25
> 2015-05-11 13:03:40,498 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Trying to deploy VM, vm has dcId: 1 and podId: null
> 2015-05-11 13:03:40,498 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Deploy avoids pods: null, clusters: null, hosts: null
> 2015-05-11 13:03:40,501 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Deploy avoids pods: null, clusters: null, hosts: null
> 2015-05-11 13:03:40,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@eb6d585
> 2015-05-11 13:03:40,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
> 2015-05-11 13:03:40,502 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Is ROOT volume READY (pool already allocated)?: No
> 2015-05-11 13:03:40,502 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Searching all possible resources under this Zone: 1
> 2015-05-11 13:03:40,503 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2015-05-11 13:03:40,510 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking resources in Cluster: 1 under Pod: 1
> 2015-05-11 13:03:40,510 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
> 2015-05-11 13:03:40,512 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2015-05-11 13:03:40,515 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2015-05-11 13:03:40,516 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
> 2015-05-11 13:03:40,521 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:40, speed:2299) to support requested CPU: 1 and requested speed: 500
> 2015-05-11 13:03:40,521 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0
> 2015-05-11 13:03:40,522 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
> 2015-05-11 13:03:40,523 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Free CPU: 91460 , Requested CPU: 500
> 2015-05-11 13:03:40,523 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Free RAM: 269692436480 , Requested RAM: 536870912
> 2015-05-11 13:03:40,523 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Host has enough CPU and RAM available
> 2015-05-11 13:03:40,523 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 500, reserved: 0, actual total: 91960, total with overprovisioning: 91960; requested cpu:500,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-11 13:03:40,523 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1073741824, reserved: 0, total: 270766178304; requested mem: 536870912,alloc_from_last_host?:false ,considerReservedCapacity?: true
> 2015-05-11 13:03:40,523 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
> 2015-05-11 13:03:40,523 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts
> 2015-05-11 13:03:40,524 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking suitable pools for volume (Id, Type): (27,ROOT)
> 2015-05-11 13:03:40,524 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) We need to allocate new storagepool for this volume
> 2015-05-11 13:03:40,525 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Calling StoragePoolAllocators to find suitable pools
> 2015-05-11 13:03:40,525 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2015-05-11 13:03:40,525 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) ClusterScopeStoragePoolAllocator looking for storage pool
> 2015-05-11 13:03:40,526 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Looking for pools in dc: 1  pod:1  cluster:1
> 2015-05-11 13:03:40,526 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Found pools matching tags: [Pool[1|SharedMountPoint]]
> 2015-05-11 13:03:40,527 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Removing pool Pool[1|SharedMountPoint] from avoid set, must have been inserted when searching for another disk's tag
> 2015-05-11 13:03:40,528 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking if storage pool is suitable, name: null ,poolId: 1
> 2015-05-11 13:03:40,531 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking pool 1 for storage, totalSize: 3246640242688, usedBytes: 513314816, usedPct: 1.581064662634163E-4, disable threshold: 0.85
> 2015-05-11 13:03:40,534 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Found storage pool primary of type SharedMountPoint
> 2015-05-11 13:03:40,534 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Total capacity of the pool primary id: 1 is 3246640242688
> 2015-05-11 13:03:40,535 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking pool: 1 for volume allocation [Vol[27|vm=27|ROOT]], maxSize : 3246640242688, totalAllocatedSize : 0, askingSize : 0, allocated disable threshold: 0.85
> 2015-05-11 13:03:40,535 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2015-05-11 13:03:40,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM
> 2015-05-11 13:03:40,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking if host: 1 can access any suitable storage pool for volume: ROOT
> 2015-05-11 13:03:40,535 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Host: 1 can access pool: 1
> 2015-05-11 13:03:40,536 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Found a potential host id: 1 name: cstkvm1 and associated storage pools for this VM
> 2015-05-11 13:03:40,536 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) 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(27|ROOT-->Pool(1))]
> 2015-05-11 13:03:40,536 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Deployment found  - P0=VM[SecondaryStorageVm|s-27-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(27|ROOT-->Pool(1))]
> 2015-05-11 13:03:40,542 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) 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-05-11 13:03:40,547 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
> 2015-05-11 13:03:40,548 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) We are allocating VM, increasing the used capacity of this host:1
> 2015-05-11 13:03:40,548 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Current Used CPU: 500 , Free CPU:91460 ,Requested CPU: 500
> 2015-05-11 13:03:40,548 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Current Used RAM: 1073741824 , Free RAM:269692436480 ,Requested RAM: 536870912
> 2015-05-11 13:03:40,548 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) CPU STATS after allocation: for host: 1, old used: 500, old reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used:1000, reserved:0; requested cpu:500,alloc_from_last:false
> 2015-05-11 13:03:40,548 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) RAM STATS after allocation: for host: 1, old used: 1073741824, old reserved: 0, total: 270766178304; new used: 1610612736, reserved: 0; requested mem: 536870912,alloc_from_last:false
> 2015-05-11 13:03:40,549 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) VM is being created in podId: 1
> 2015-05-11 13:03:40,553 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Network id=200 is already implemented
> 2015-05-11 13:03:40,564 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Network id=202 is already implemented
> 2015-05-11 13:03:40,579 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Network id=201 is already implemented
> 2015-05-11 13:03:40,590 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Allocated a nic NicProfile[106-27-ef7c249f-d533-4f39-b992-41efcbdfae25-10.204.196.35-null for VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,594 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Network id=203 is already implemented
> 2015-05-11 13:03:40,607 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Allocated a nic NicProfile[107-27-ef7c249f-d533-4f39-b992-41efcbdfae25-10.204.196.73-null for VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,610 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking if we need to prepare 1 volumes for VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:40,618 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) template 3 is already in store:1, type:Image
> 2015-05-11 13:03:40,620 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) template 3 is already in store:1, type:Primary
> 2015-05-11 13:03:40,629 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
> 2015-05-11 13:03:40,636 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702015: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"ffbb0fe0-f406-11e4-8193-005056997f17","origUrl":"http://cloudstack.apt-get.eu/systemvm/4.4/systemvm64template-4.4.0-6-kvm.qcow2.bz2","uuid":"ffbb0fe0-f406-11e4-8193-005056997f17","id":3,"format":"QCOW2","accountId":1,"checksum":"770a7d3b727ca15e511c33521ef5b8ba","hvm":false,"displayText":"SystemVM Template (KVM)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2cde1151-a6ca-472c-88a4-6af6175d31ba","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=2cde1151-a6ca-472c-88a4-6af6175d31ba"}},"name":"routing-3","hypervisorType":"KVM"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2cde1151-a6ca-472c-88a4-6af6175d31ba","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=2cde1151-a6ca-472c-88a4-6af6175d31ba"}},"name":"ROOT-27","size":0,"volumeId":27,"vmName":"s-27-VM","accountId":1,"format":"QCOW2","id":27,"deviceId":0,"hypervisorType":"KVM"}},"executeInSequence":false,"options":{},"wait":0}}] }
> 2015-05-11 13:03:40,690 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null) Seq 1-4664884789025702015: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"size":0,"path":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","accountId":0,"format":"QCOW2","id":0}},"result":true,"wait":0}}] }
> 2015-05-11 13:03:40,690 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702015: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } }
> 2015-05-11 13:03:40,709 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) VmWare hypervisor configured, telling the ssvm to load the PremiumSecondaryStorageResource
> 2015-05-11 13:03:40,711 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Boot Args for VM[SecondaryStorageVm|s-27-VM]:  template=domP type=secstorage host=10.204.206.8 port=8250 name=s-27-VM zone=1 pod=1 guid=s-27-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=10.204.195.2 eth2mask=255.255.240.0 gateway=10.204.207.254 public.network.device=eth2 eth0ip=169.254.0.247 eth0mask=255.255.0.0 eth1ip=10.204.196.35 eth1mask=255.255.240.0 mgmtcidr=10.204.192.0/20 localgw=10.204.207.254 private.network.device=eth1 eth3ip=10.204.196.73 eth3mask=255.255.240.0 storageip=10.204.196.73 storagenetmask=255.255.240.0 storagegateway=10.204.207.254 internaldns1=10.206.66.12 dns1=172.21.0.15
> 2015-05-11 13:03:40,732 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702016: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StartCommand":{"vm":{"id":27,"name":"s-27-VM","type":"SecondaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","platformEmulator":"Debian GNU/Linux 5","bootArgs":" template=domP type=secstorage host=10.204.206.8 port=8250 name=s-27-VM zone=1 pod=1 guid=s-27-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=10.204.195.2 eth2mask=255.255.240.0 gateway=10.204.207.254 public.network.device=eth2 eth0ip=169.254.0.247 eth0mask=255.255.0.0 eth1ip=10.204.196.35 eth1mask=255.255.240.0 mgmtcidr=10.204.192.0/20 localgw=10.204.207.254 private.network.device=eth1 eth3ip=10.204.196.73 eth3mask=255.255.240.0 storageip=10.204.196.73 storagenetmask=255.255.240.0 storagegateway=10.204.207.254 internaldns1=10.206.66.12 dns1=172.21.0.15","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"daa3d95a7908f256","params":{},"uuid":"0eeb59db-12bb-4a75-bf35-ad9927b5a0b2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2cde1151-a6ca-472c-88a4-6af6175d31ba","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=2cde1151-a6ca-472c-88a4-6af6175d31ba"}},"name":"ROOT-27","size":0,"path":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","volumeId":27,"vmName":"s-27-VM","accountId":1,"format":"QCOW2","id":27,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"localhost","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"nicUuid":"3b7c7294-6725-46a3-8603-44dc394ca09c","uuid":"97575f7f-3f92-4e33-bcca-ffdd065f5c61","ip":"10.204.195.2","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:e6:7e:00:01:00","dns1":"172.21.0.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"166dc02d-35f0-43f3-a09a-133161813f7c","uuid":"c84ea23e-f71d-44d4-ae93-4444a39f156d","ip":"169.254.0.247","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:00:f7","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"711173a8-cb34-4fca-82ca-5517a34058f3","uuid":"484970d9-da8e-48fb-a369-084d2ec5d565","ip":"10.204.196.35","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:40:1e:00:00:23","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"add6373d-76e6-43bc-9f47-2670ba80cf80","uuid":"b3b94e14-df17-4726-8baa-bd40ca63b269","ip":"10.204.196.73","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:c4:9c:00:00:49","broadcastType":"Native","type":"Storage","isSecurityGroupEnabled":false,"name":"cloudbr0"}]},"hostIp":"10.204.206.7","executeInSequence":false,"wait":0}},{"com.cloud.agent.api.check.CheckSshCommand":{"ip":"169.254.0.247","port":3922,"interval":6,"retries":100,"name":"s-27-VM","wait":0}}] }
> 2015-05-11 13:03:40,985 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) Seq 1-4664884789025702016: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":27,"name":"s-27-VM","type":"SecondaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 5.0 (64-bit)","platformEmulator":"Debian GNU/Linux 5","bootArgs":" template=domP type=secstorage host=10.204.206.8 port=8250 name=s-27-VM zone=1 pod=1 guid=s-27-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=10.204.195.2 eth2mask=255.255.240.0 gateway=10.204.207.254 public.network.device=eth2 eth0ip=169.254.0.247 eth0mask=255.255.0.0 eth1ip=10.204.196.35 eth1mask=255.255.240.0 mgmtcidr=10.204.192.0/20 localgw=10.204.207.254 private.network.device=eth1 eth3ip=10.204.196.73 eth3mask=255.255.240.0 storageip=10.204.196.73 storagenetmask=255.255.240.0 storagegateway=10.204.207.254 internaldns1=10.206.66.12 dns1=172.21.0.15","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"daa3d95a7908f256","vncAddr":"10.204.206.7","params":{},"uuid":"0eeb59db-12bb-4a75-bf35-ad9927b5a0b2","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"2cde1151-a6ca-472c-88a4-6af6175d31ba","id":1,"poolType":"SharedMountPoint","host":"localhost","path":"/cst/primary","port":0,"url":"SharedMountPoint://localhost/cst/primary/?ROLE=Primary&STOREUUID=2cde1151-a6ca-472c-88a4-6af6175d31ba"}},"name":"ROOT-27","size":0,"path":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","volumeId":27,"vmName":"s-27-VM","accountId":1,"format":"QCOW2","id":27,"deviceId":0,"hypervisorType":"KVM"}},"diskSeq":0,"path":"d05cc02c-41d0-4de9-ab33-48e4411ab6c2","type":"ROOT","_details":{"managed":"false","storagePort":"0","storageHost":"localhost","volumeSize":"0"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"nicUuid":"3b7c7294-6725-46a3-8603-44dc394ca09c","uuid":"97575f7f-3f92-4e33-bcca-ffdd065f5c61","ip":"10.204.195.2","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:e6:7e:00:01:00","dns1":"172.21.0.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://untagged","isolationUri":"vlan://untagged","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"166dc02d-35f0-43f3-a09a-133161813f7c","uuid":"c84ea23e-f71d-44d4-ae93-4444a39f156d","ip":"169.254.0.247","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:00:f7","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"711173a8-cb34-4fca-82ca-5517a34058f3","uuid":"484970d9-da8e-48fb-a369-084d2ec5d565","ip":"10.204.196.35","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:40:1e:00:00:23","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false,"name":"cloudbr0"},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"nicUuid":"add6373d-76e6-43bc-9f47-2670ba80cf80","uuid":"b3b94e14-df17-4726-8baa-bd40ca63b269","ip":"10.204.196.73","netmask":"255.255.240.0","gateway":"10.204.207.254","mac":"06:c4:9c:00:00:49","broadcastType":"Native","type":"Storage","isSecurityGroupEnabled":false,"name":"cloudbr0"}]},"result":false,"details":"Unable to add port vnet4 to OVS bridge cloudbr0: Operation not permitted","wait":0}},{"com.cloud.agent.api.Answer":{"result":false,"details":"Stopped by previous failure","wait":0}}] }
> 2015-05-11 13:03:40,986 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702016: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { StartAnswer, Answer } }
> 2015-05-11 13:03:40,988 INFO  [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Unable to start VM on Host[-1-Routing] due to Unable to add port vnet4 to OVS bridge cloudbr0: Operation not permitted
> 2015-05-11 13:03:40,989 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Cleaning up resources for the vm VM[SecondaryStorageVm|s-27-VM] in Starting state
> 2015-05-11 13:03:40,992 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702017: Sending  { Cmd , MgmtId: 345050283799, via: 1(cstkvm1), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"s-27-VM","wait":0}}] }
> 2015-05-11 13:03:41,142 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) Seq 1-4664884789025702017: Processing:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:41,142 DEBUG [c.c.a.t.Request] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Seq 1-4664884789025702017: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
> 2015-05-11 13:03:41,149 DEBUG [c.c.n.g.ControlNetworkGuru] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Released nic: NicProfile[105-27-null-null-null
> 2015-05-11 13:03:41,154 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Releasing ip address for reservationId=ef7c249f-d533-4f39-b992-41efcbdfae25, instance=106
> 2015-05-11 13:03:41,155 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Released nic: NicProfile[106-27-null-null-null
> 2015-05-11 13:03:41,161 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Releasing ip address for reservationId=ef7c249f-d533-4f39-b992-41efcbdfae25, instance=107
> 2015-05-11 13:03:41,161 DEBUG [c.c.n.g.PodBasedNetworkGuru] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Released nic: NicProfile[107-27-null-null-null
> 2015-05-11 13:03:41,163 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Successfully released network resources for the vm VM[SecondaryStorageVm|s-27-VM]
> 2015-05-11 13:03:41,164 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Successfully cleanued up resources for the vm VM[SecondaryStorageVm|s-27-VM] in Starting state
> 2015-05-11 13:03:41,165 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Root volume is ready, need to place VM in volume's cluster
> 2015-05-11 13:03:41,165 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Vol[27|vm=27|ROOT] is READY, changing deployment plan to use this pool's dcId: 1 , podId: 1 , and clusterId: 1
> 2015-05-11 13:03:41,167 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Deploy avoids pods: null, clusters: null, hosts: [1]
> 2015-05-11 13:03:41,168 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@eb6d585
> 2015-05-11 13:03:41,168 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 500, requested ram: 536870912
> 2015-05-11 13:03:41,168 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Is ROOT volume READY (pool already allocated)?: Yes
> 2015-05-11 13:03:41,168 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Searching resources only under specified Cluster: 1
> 2015-05-11 13:03:41,172 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Checking resources in Cluster: 1 under Pod: 1
> 2015-05-11 13:03:41,172 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Looking for hosts in dc: 1  pod:1  cluster:1
> 2015-05-11 13:03:41,174 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]]
> 2015-05-11 13:03:41,178 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]]
> 2015-05-11 13:03:41,178 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
> 2015-05-11 13:03:41,178 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Host name: cstkvm1, hostId: 1 is in avoid set, skipping this and trying other available hosts
> 2015-05-11 13:03:41,178 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5 FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
> 2015-05-11 13:03:41,178 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) No suitable hosts found
> 2015-05-11 13:03:41,178 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) No suitable hosts found under this Cluster: 1
> 2015-05-11 13:03:41,179 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Could not find suitable Deployment Destination for this VM under any clusters, returning. 
> 2015-05-11 13:03:41,179 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Searching resources only under specified Cluster: 1
> 2015-05-11 13:03:41,180 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) The specified cluster is in avoid set, returning.
> 2015-05-11 13:03:41,181 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Deploy avoids pods: null, clusters: [1], hosts: [1]
> 2015-05-11 13:03:41,182 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@eb6d585
> 2015-05-11 13:03:41,182 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Trying to allocate a host and storage pools from dc:1, pod:null,cluster:null, requested cpu: 500, requested ram: 536870912
> 2015-05-11 13:03:41,182 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Is ROOT volume READY (pool already allocated)?: No
> 2015-05-11 13:03:41,182 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Searching all possible resources under this Zone: 1
> 2015-05-11 13:03:41,183 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2015-05-11 13:03:41,185 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Removing from the clusterId list these clusters from avoid set: [1]
> 2015-05-11 13:03:41,186 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) No clusters found after removing disabled clusters and clusters in avoid list, returning.
> 2015-05-11 13:03:41,192 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) 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-05-11 13:03:41,196 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Hosts's actual total CPU: 91960 and CPU after applying overprovisioning: 91960
> 2015-05-11 13:03:41,196 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Hosts's actual total RAM: 270766170112 and RAM after applying overprovisioning: 270766178304
> 2015-05-11 13:03:41,197 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 91960, total with overprovisioning: 91960; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2015-05-11 13:03:41,197 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) release mem from host: 1, old used: 1610612736,reserved: 0, total: 270766178304; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2015-05-11 13:03:41,198 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-27-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> 2015-05-11 13:03:41,199 INFO  [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113 ctx-4091b6b5) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-27-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> 2015-05-11 13:03:41,199 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 4
> 2015-05-11 13:03:41,199 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Unable to complete AsyncJobVO {id:113, userId: 1, accountId: 1, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAABAAAAAAAAAAEAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 345050283799, completeMsid: null, lastUpdated: null, lastPolled: null, created: Mon May 11 13:03:40 IST 2015}, job origin:4
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-27-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:5201)
>         at sun.reflect.GeneratedMethodAccessor227.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:5346)
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
>         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:459)
>         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-05-11 13:03:41,201 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Complete async job-113, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAXEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bU2Vjb25kYXJ5U3RvcmFnZVZtfHMtMjctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH2dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHLcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
> 2015-05-11 13:03:41,205 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Done executing com.cloud.vm.VmWorkStart for job-113
> 2015-05-11 13:03:41,212 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Sync queue (77) is currently empty
> 2015-05-11 13:03:41,212 INFO  [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-45:ctx-1e244c96 job-4/job-113) Remove job-113 from job monitoring
> 2015-05-11 13:03:41,214 WARN  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) 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-27-VM]
>         at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
>         at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:502)
>         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:459)
>         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-05-11 13:03:41,215 INFO  [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 27, will recycle it and start a new one
> 2015-05-11 13:03:41,216 INFO  [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-febdd7c0) Primary secondary storage is not even started, wait until next turn
> 2015-05-11 13:03:44,843 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-274: Processing Seq 2-274:  { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":1,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
> 2015-05-11 13:03:44,847 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-274: Sending Seq 2-274:  { Ans: , MgmtId: 345050283799, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-05-11 13:03:47,495 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-a4e79bc1) HostStatsCollector is running...
> 2015-05-11 13:03:47,508 INFO  [c.c.a.t.Request] (StatsCollector-1:ctx-a4e79bc1) not building log message for '[{}]', _cmds.length == 1
> 2015-05-11 13:03:48,056 INFO  [c.c.a.t.Request] (AgentManager-Handler-3:null) not building log message for '[{}]', _cmds.length == 1
> 2015-05-11 13:03:48,057 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-a4e79bc1) Seq 1-4664884789025702018: Received:  { Ans: , MgmtId: 345050283799, via: 1, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> ^C
> [root@cstmgt ~]# 



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message