Nagaraju created CLOUDSTACK-8454:
------------------------------------
Summary: 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)
