Here is the managemnt logs:
2014-12-01 11:06:03,560 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-2f06bbbe) Seq 1-4157385406016389183: Response Received:
2014-12-01 11:06:03,560 DEBUG [c.c.a.t.Request] (DirectAgent-1:ctx-2f06bbbe)
Seq 1-4157385406016389183: Processing: { Ans: , MgmtId: 52239450489, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"Stop VM s-2-VM
Succeed","wait":0}}] }
2014-12-01 11:06:03,560 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Seq
1-4157385406016389183: Received: { Ans: , MgmtId: 52239450489, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2014-12-01 11:06:03,560 DEBUG [c.c.a.m.AgentManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Details from
executing class com.cloud.agent.api.StopCommand: Stop VM s-2-VM Succeed
2014-12-01 11:06:03,561 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Failed to start
instance VM[SecondaryStorageVm|s-2-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1073)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2014-12-01 11:06:03,567 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Cleaning up
resources for the vm VM[SecondaryStorageVm|s-2-VM] in Starting state
2014-12-01 11:06:03,572 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Seq
1-4157385406016389185: Sending { Cmd , MgmtId: 52239450489, via:
1(172.28.52.4), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"s-2-VM","wait":0}}] }
2014-12-01 11:06:03,572 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Seq
1-4157385406016389185: Executing: { Cmd , MgmtId: 52239450489, via:
1(172.28.52.4), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"s-2-VM","wait":0}}] }
2014-12-01 11:06:03,573 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-18:ctx-77f9412b) Seq 1-4157385406016389185: Executing request
2014-12-01 11:06:03,574 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-18:ctx-77f9412b 172.28.52.4) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmNam
e":"s-2-VM","wait":0}
2014-12-01 11:06:03,641 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-18:ctx-77f9412b 172.28.52.4) find VM s-2-VM on host
2014-12-01 11:06:03,641 INFO [c.c.h.v.m.HostMO]
(DirectAgent-18:ctx-77f9412b 172.28.52.4) VM s-2-VM not found in host cache
2014-12-01 11:06:03,642 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-18:ctx-77f9412b 172.28.52.4) load VM cache on host
2014-12-01 11:06:03,729 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-18:ctx-77f9412b 172.28.52.4) VM s-2-VM is already in stopped
state
2014-12-01 11:06:03,729 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-18:ctx-77f9412b) Seq 1-4157385406016389185: Response Received:
2014-12-01 11:06:03,730 DEBUG [c.c.a.t.Request]
(DirectAgent-18:ctx-77f9412b) Seq 1-4157385406016389185: Processing: { Ans:
, MgmtId: 52239450489, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM s-2-VM is
already in stopped state","wait":0}}] }
2014-12-01 11:06:03,730 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Seq
1-4157385406016389185: Received: { Ans: , MgmtId: 52239450489, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2014-12-01 11:06:03,797 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Releasing ip
address for reservationId=7bedc0a4-cfa3-486d-8204-c7cf28cdab74, instance=6
2014-12-01 11:06:03,798 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Released nic:
NicProfile[6-2-null-null-null
2014-12-01 11:06:03,813 DEBUG [c.c.n.g.StorageNetworkGuru]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Release an
storage ip 172.28.53.100
2014-12-01 11:06:03,817 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Successfully
released network resources for the vm VM[SecondaryStorageVm|s-2-VM]
2014-12-01 11:06:03,818 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Successfully
cleanued up resources for the vm VM[SecondaryStorageVm|s-2-VM] in Starting
state
2014-12-01 11:06:03,830 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) 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
2014-12-01 11:06:03,841 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Hosts's actual
total CPU: 38384 and CPU after applying overprovisioning: 38384
2014-12-01 11:06:03,841 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Hosts's actual
total RAM: 120248320000 and RAM after applying overprovisioning:
120248320000
2014-12-01 11:06:03,842 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) release cpu
from host: 1, old used: 1000,reserved: 0, actual total: 38384, total with
overprovisioning: 38384; new used: 500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2014-12-01 11:06:03,842 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) release mem
from host: 1, old used: 1610612736,reserved: 0, total: 120248320000; new
used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
2014-12-01 11:06:03,845 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Invocation
exception, caused by: com.cloud.exception.AgentUnavailableException:
Resource [Host:1] is unreachable: Host 1: Unable to start instance due to
Unable to start VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart,
not retrying
2014-12-01 11:06:03,845 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86 ctx-bdae7320) Rethrow
exception com.cloud.exception.AgentUnavailableException: Resource [Host:1]
is unreachable: Host 1: Unable to start instance due to Unable to start
VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart, not retrying
2014-12-01 11:06:03,845 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Done with run of VM work
job: com.cloud.vm.VmWorkStart for VM 2, job origin: 2
2014-12-01 11:06:03,845 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Unable to complete
AsyncJobVO {id:86, userId: 1, accountId: 1, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9p
ZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAlj
bHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQA
EkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-
AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01h
cDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAE
SgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAAB
AAAAAAAAAAEAAAAAAAAAAnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBw
cHBwcHA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode:
0, result: null, initMsid: 52239450489, completeMsid: null, lastUpdated:
null, lastPolled: null, created: Mon Dec 01 10:48:05 IRST 2014}, job
origin:2
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to Unable to start
VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1106)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1073)
... 20 more
2014-12-01 11:06:03,861 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-32:ctx-7d0ed237) Seq 1-4157385406016389182: Response Received:
2014-12-01 11:06:03,862 DEBUG [c.c.a.t.Request]
(DirectAgent-32:ctx-7d0ed237) Seq 1-4157385406016389182: Processing: { Ans:
, MgmtId: 52239450489, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"Stop VM v-1-VM
Succeed","wait":0}}] }
2014-12-01 11:06:03,862 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Complete async job-86,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFu
Zy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARM
AAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9s
YW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7
TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAv0pvYiBm
YWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBSZXNvdXJjZSBbSG9zdDoxXSBpcyB1bnJlYWNoYWJsZTog
SG9zdCAxOiBVbmFibGUgdG8gc3RhcnQgaW5zdGFuY2UgZHVlIHRvIFVuYWJsZSB0byBzdGFydCBW
TVtTZWNvbmRhcnlTdG9yYWdlVm18cy0yLVZNXSBkdWUgdG8gZXJyb3IgaW4gZmluYWxpemVTdGFy
dCwgbm90IHJldHJ5aW5ndXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5
AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGlu
ZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFt
ZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtK
b2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dAA_b3JnLmFwYWNoZS5jbG91ZHN0
YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JN
YW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xv
dWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdl
ZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRz
dGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1
bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vk
c3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9j
YWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgAL
AAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRl
eHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QA
LmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRv
cnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0
AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5U
aHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNx
AH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2Vy
cQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4A
F3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAE
bGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9u
GUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5B
cnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
2014-12-01 11:06:03,862 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Seq
1-4157385406016389182: Received: { Ans: , MgmtId: 52239450489, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2014-12-01 11:06:03,862 DEBUG [c.c.a.m.AgentManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Details from
executing class com.cloud.agent.api.StopCommand: Stop VM v-1-VM Succeed
2014-12-01 11:06:03,862 ERROR [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Failed to start
instance VM[ConsoleProxy|v-1-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM[ConsoleProxy|v-1-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:1073)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManage
rImpl.java:5195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57
)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl
.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.jav
a:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManager
Impl.java:5340)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2014-12-01 11:06:03,893 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Cleaning up
resources for the vm VM[ConsoleProxy|v-1-VM] in Starting state
2014-12-01 11:06:03,895 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Done executing
com.cloud.vm.VmWorkStart for job-86
2014-12-01 11:06:03,902 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Seq
1-4157385406016389186: Sending { Cmd , MgmtId: 52239450489, via:
1(172.28.52.4), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"v-1-VM","wait":0}}] }
2014-12-01 11:06:03,902 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Seq
1-4157385406016389186: Executing: { Cmd , MgmtId: 52239450489, via:
1(172.28.52.4), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":fal
se,"checkBeforeCleanup":false,"vmName":"v-1-VM","wait":0}}] }
2014-12-01 11:06:03,902 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-34:ctx-60e0d9c8) Seq 1-4157385406016389186: Executing request
2014-12-01 11:06:03,903 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) Executing resource StopCommand:
{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmNam
e":"v-1-VM","wait":0}
2014-12-01 11:06:03,912 WARN [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-fae86aa6) Exception while trying to start secondary
storage vm
java.lang.RuntimeException: Job failed due to exception Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to Unable to start
VM[SecondaryStorageVm|s-2-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext
(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedCo
ntextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(Defa
ultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2014-12-01 11:06:03,915 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-fae86aa6) Unable to start secondary storage vm for standby
capacity, secStorageVm vm Id : 2, will recycle it and start a new one
2014-12-01 11:06:03,915 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-fae86aa6) Primary secondary storage is not even started,
wait until next turn
2014-12-01 11:06:03,939 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) Zone 3 is ready to launch secondary storage VM
2014-12-01 11:06:03,946 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) No running secondary storage vms found in
datacenter id=3, starting one
2014-12-01 11:06:03,952 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Sync queue (2) is currently
empty
2014-12-01 11:06:03,953 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Remove job-86 from job
monitoring
2014-12-01 11:06:03,959 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) Found a stopped secondary storage vm, bring it
up to running pool. secStorageVm vm id : 2
2014-12-01 11:06:03,971 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) find VM v-1-VM on host
2014-12-01 11:06:03,972 INFO [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) VM v-1-VM not found in host cache
2014-12-01 11:06:03,972 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) load VM cache on host
2014-12-01 11:06:03,975 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(secstorage-1:ctx-c961e98c) Sync job-87 execution on object VmWorkJobQueue.2
2014-12-01 11:06:03,978 WARN [c.c.u.d.Merovingian2]
(secstorage-1:ctx-c961e98c) Was unable to find lock for the key vm_instance2
and thread id 113798733
2014-12-01 11:06:04,101 INFO [c.c.h.v.r.VmwareResource]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) VM v-1-VM is already in stopped
state
2014-12-01 11:06:04,102 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-34:ctx-60e0d9c8) Seq 1-4157385406016389186: Response Received:
2014-12-01 11:06:04,102 DEBUG [c.c.a.t.Request]
(DirectAgent-34:ctx-60e0d9c8) Seq 1-4157385406016389186: Processing: { Ans:
, MgmtId: 52239450489, via: 1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM v-1-VM is
already in stopped state","wait":0}}] }
2014-12-01 11:06:04,111 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Seq
1-4157385406016389186: Received: { Ans: , MgmtId: 52239450489, via: 1, Ver:
v1, Flags: 10, { StopAnswer } }
2014-12-01 11:06:04,135 DEBUG [c.c.d.d.DataCenterIpAddressDaoImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Releasing ip
address for reservationId=6bbcd02e-33f2-4b4e-aa86-a7df34a54896, instance=3
2014-12-01 11:06:04,137 DEBUG [c.c.n.g.PodBasedNetworkGuru]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Released nic:
NicProfile[3-1-null-null-null
2014-12-01 11:06:04,142 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Successfully
released network resources for the vm VM[ConsoleProxy|v-1-VM]
2014-12-01 11:06:04,142 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Successfully
cleanued up resources for the vm VM[ConsoleProxy|v-1-VM] in Starting state
2014-12-01 11:06:04,154 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) 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
2014-12-01 11:06:04,163 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-1:ctx-67701c0c job-1/job-85 ctx-a98d5a22) Hosts's actual
total CPU: 38384 and CPU after applying overprovisioning: 38384
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithCon
text(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCont
ext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCont
extRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJob
ManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:11
45)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:6
15)
at java.lang.Thread.run(Thread.java:745)
2014-12-01 11:06:03,915 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-fae86aa6) Unable to start secondary storage vm
for standby capacity, secStorageVm vm Id : 2, will recycle it and start a
new one
2014-12-01 11:06:03,915 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-fae86aa6) Primary secondary storage is
not even started, wait until next turn
2014-12-01 11:06:03,939 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) Zone 3 is ready to launch secondary
storage VM
2014-12-01 11:06:03,946 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) No running secondary storage
vms found in datacenter id=3, starting one
2014-12-01 11:06:03,952 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Sync queue (2) is c
urrently empty
2014-12-01 11:06:03,953 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-2:ctx-ccf9c7d8 job-2/job-86) Remove job-86 from job m
onitoring
2014-12-01 11:06:03,959 INFO [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-c961e98c) Found a stopped secondary storage vm
, bring it up to running pool. secStorageVm vm id : 2
2014-12-01 11:06:03,971 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) find VM v-1-VM on host
2014-12-01 11:06:03,972 INFO [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) VM v-1-VM not found in host cache
2014-12-01 11:06:03,972 DEBUG [c.c.h.v.m.HostMO]
(DirectAgent-34:ctx-60e0d9c8 172.28.52.4) load VM cache on host
2014-12-01 11:06:03,975 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(secstorage-1:ctx-c961e98c) Sync job-87 execution on object VmWorkJo
bQueue.2
2014-12-01 11:06:03,978 WARN [c.c.u.d.Merovingian2]
(secstorage-1:ctx-c961e98c) Was unable to find lock for the key vm_instance2
an
d thread id 113798733
