[
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)
