Ok updated value in database. But now if I try to start VM in CloudStack its
giving new error.
Can you check attached log file?
It was totally fine and up, I don’t know what happened. On last Friday I
configured HA. It looked fine, After that there was no other changes in
CloudStack.
/sonali
-----Original Message-----
From: Geoff Higginbottom [mailto:geoff.higginbot...@shapeblue.com]
Sent: Friday, January 16, 2015 2:44 PM
To: users@cloudstack.apache.org
Subject: RE: Help! cant perform any operation on VMs
What state does CloudStack 'think' the VR is in and what state is it actually
in?
Assuming it is running but CloudStack thinks its stopped, mark it as Running in
the DB (table vm_instance), then stop it from CloudStack, and then start it
from CloudStack.
Regards
Geoff Higginbottom
D: +44 20 3603 0542 | S: +44 20 3603 0540 | M: +447968161581
geoff.higginbot...@shapeblue.com
-----Original Message-----
From: Sonali Jadhav [mailto:son...@servercentralen.se]
Sent: 16 January 2015 09:07
To: users@cloudstack.apache.org
Subject: RE: Help! cant perform any operation on VMs
Hi yes I did.
I have even applied all available updates for XenServer 6.2, to be sure.
I even restarted management service.
/Sonali
-----Original Message-----
From: Geoff Higginbottom [mailto:geoff.higginbot...@shapeblue.com]
Sent: Friday, January 16, 2015 2:27 PM
To: users@cloudstack.apache.org
Subject: RE: Help! cant perform any operation on VMs
Sonali,
Have you tried restarting the VR?
Regards
Geoff Higginbottom
D: +44 20 3603 0542 | S: +44 20 3603 0540 | M: +447968161581
geoff.higginbot...@shapeblue.com
-----Original Message-----
From: Sonali Jadhav [mailto:son...@servercentralen.se]
Sent: 16 January 2015 08:54
To: users@cloudstack.apache.org
Subject: Help! cant perform any operation on VMs
Hi,
My all instances are stopped on CloudStack but in fact they are up on hosts. If
I try to start instance from CloudStack it throws this error "Job failed due to
exception Resource [Host:6] is unreachable: Host 6: Unable to start instance
due to Unable to change the state of VM[DomainRouter|r-4-VM]"
2015-01-16 09:15:00,156 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-5:ctx-4f63f9e8 job-299) Unexpected exception while executing
org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
2015-01-16 09:15:00,157 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-5:ctx-4f63f9e8 job-299) Complete async job-299, jobStatus:
FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Job
failed due to exception Resource [Host:6] is unreachable: Host 6: Unable to
start instance due to Unable to change the state of VM[DomainRouter|r-4-VM]"}
r-4-VM is a virtual router. In CloudStack it says status "starting" but it's up
on host.
I have cluster of 4 Hosts. With HA enabled as per Geoff's guide
http://shapeblue.com/cloudstack/xenserver-native-ha-with-cloudstack
Right now I have only one virtual router and 4 VMs in same isolated network.
And on all those I can't perform any function.
Yours sincerely,
Sonali Jadhav | System Administrator
Nordiska Servercentralen
Find out more about ShapeBlue and our range of CloudStack related services
IaaS Cloud Design & Build<http://shapeblue.com/iaas-cloud-design-and-build//>
CSForge – rapid IaaS deployment framework<http://shapeblue.com/csforge/>
CloudStack Consulting<http://shapeblue.com/cloudstack-consultancy/>
CloudStack Software
Engineering<http://shapeblue.com/cloudstack-software-engineering/>
CloudStack Infrastructure
Support<http://shapeblue.com/cloudstack-infrastructure-support/>
CloudStack Bootcamp Training Courses<http://shapeblue.com/cloudstack-training/>
This email and any attachments to it may be confidential and are intended
solely for the use of the individual to whom it is addressed. Any views or
opinions expressed are solely those of the author and do not necessarily
represent those of Shape Blue Ltd or related companies. If you are not the
intended recipient of this email, you must neither take any action based upon
its contents, nor copy or show it to anyone. Please contact the sender if you
believe you have received this email in error. Shape Blue Ltd is a company
incorporated in England & Wales. ShapeBlue Services India LLP is a company
incorporated in India and is operated under license from Shape Blue Ltd. Shape
Blue Brasil Consultoria Ltda is a company incorporated in Brasil and is
operated under license from Shape Blue Ltd. ShapeBlue SA Pty Ltd is a company
registered by The Republic of South Africa and is traded under license from
Shape Blue Ltd. ShapeBlue is a registered trademark.
Find out more about ShapeBlue and our range of CloudStack related services
IaaS Cloud Design & Build<http://shapeblue.com/iaas-cloud-design-and-build//>
CSForge – rapid IaaS deployment framework<http://shapeblue.com/csforge/>
CloudStack Consulting<http://shapeblue.com/cloudstack-consultancy/>
CloudStack Software
Engineering<http://shapeblue.com/cloudstack-software-engineering/>
CloudStack Infrastructure
Support<http://shapeblue.com/cloudstack-infrastructure-support/>
CloudStack Bootcamp Training Courses<http://shapeblue.com/cloudstack-training/>
This email and any attachments to it may be confidential and are intended
solely for the use of the individual to whom it is addressed. Any views or
opinions expressed are solely those of the author and do not necessarily
represent those of Shape Blue Ltd or related companies. If you are not the
intended recipient of this email, you must neither take any action based upon
its contents, nor copy or show it to anyone. Please contact the sender if you
believe you have received this email in error. Shape Blue Ltd is a company
incorporated in England & Wales. ShapeBlue Services India LLP is a company
incorporated in India and is operated under license from Shape Blue Ltd. Shape
Blue Brasil Consultoria Ltda is a company incorporated in Brasil and is
operated under license from Shape Blue Ltd. ShapeBlue SA Pty Ltd is a company
registered by The Republic of South Africa and is traded under license from
Shape Blue Ltd. ShapeBlue is a registered trademark.
2015-01-16 10:51:50,445 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-71:ctx-848585d7) Seq 1-4700350636091244870: Response Received:
2015-01-16 10:51:50,445 DEBUG [c.c.a.t.Request] (DirectAgent-71:ctx-848585d7)
Seq 1-4700350636091244870: Processing: { Ans: , MgmtId: 59778234354585, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"","wait":0}}] }
2015-01-16 10:51:50,445 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Seq
1-4700350636091244870: Received: { Ans: , MgmtId: 59778234354585, via: 1, Ver:
v1, Flags: 10, { Answer } }
2015-01-16 10:51:50,445 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Unable to
contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
unreachable: Unable to apply dhcp entry on router
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:4018)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3134)
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
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy189.applyDhcpEntry(Unknown Source)
at
com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:905)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1221)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1343)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1279)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:986)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.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.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2015-01-16 10:51:50,497 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Cleaning up
resources for the vm VM[User|i-2-7-VM] in Starting state
2015-01-16 10:51:50,504 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Seq
4-4532873024948404466: Sending { Cmd , MgmtId: 59778234354585, via:
4(SeSolXS02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-7-VM","wait":0}}]
}
2015-01-16 10:51:50,505 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Seq
4-4532873024948404466: Executing: { Cmd , MgmtId: 59778234354585, via:
4(SeSolXS02), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-7-VM","wait":0}}]
}
2015-01-16 10:51:50,505 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-142:ctx-6c39dedf) Seq 4-4532873024948404466: Executing request
2015-01-16 10:51:50,512 INFO [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-142:ctx-6c39dedf) VM does not exist on
XenServer4ffffff9-c543-4448-8d88-d4d4e8d1db9d
2015-01-16 10:51:50,512 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-142:ctx-6c39dedf) Seq 4-4532873024948404466: Response Received:
2015-01-16 10:51:50,512 DEBUG [c.c.a.t.Request] (DirectAgent-142:ctx-6c39dedf)
Seq 4-4532873024948404466: Processing: { Ans: , MgmtId: 59778234354585, via:
4, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not
exist","wait":0}}] }
2015-01-16 10:51:50,512 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Seq
4-4532873024948404466: Received: { Ans: , MgmtId: 59778234354585, via: 4, Ver:
v1, Flags: 10, { StopAnswer } }
2015-01-16 10:51:50,528 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Service
SecurityGroup is not supported in the network id=204
2015-01-16 10:51:50,532 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Changing
active number of nics for network id=204 on -1
2015-01-16 10:51:50,588 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Asking
VirtualRouter to release
NicProfile[17-7-b4b168e4-7260-452d-850e-b4ac7e49927f-10.1.1.56-null
2015-01-16 10:51:50,588 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Successfully
released network resources for the vm VM[User|i-2-7-VM]
2015-01-16 10:51:50,589 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Successfully
cleanued up resources for the vm VM[User|i-2-7-VM] in Starting state
2015-01-16 10:51:50,596 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Root volume is
ready, need to place VM in volume's cluster
2015-01-16 10:51:50,619 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Deploy avoids
pods: [], clusters: [], hosts: [4]
2015-01-16 10:51:50,619 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) DataCenter id
= '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM,
returning.
2015-01-16 10:51:50,779 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's original
host id: 4 new host id: null host id before state transition: 4
2015-01-16 10:51:50,792 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Hosts's actual
total CPU: 57600 and CPU after applying overprovisioning: 57600
2015-01-16 10:51:50,792 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Hosts's actual
total RAM: 95574311424 and RAM after applying overprovisioning: 95574310912
2015-01-16 10:51:50,792 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) release cpu
from host: 4, old used: 1000,reserved: 0, actual total: 57600, total with
overprovisioning: 57600; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-01-16 10:51:50,792 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) release mem
from host: 4, old used: 1073741824,reserved: 0, total: 95574310912; new used:
0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-01-16 10:51:50,907 DEBUG [c.c.a.ApiServlet]
(http-6443-exec-5:ctx-a7d8fbae) ===START=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401893805
2015-01-16 10:51:50,943 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Invocation
exception, caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-2-7-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-16 10:51:50,943 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324 ctx-91e6e51c) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-7-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-16 10:51:50,943 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Done with run of VM work
job: com.cloud.vm.VmWorkStart for VM 7, job origin: 323
2015-01-16 10:51:50,943 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Unable to complete
AsyncJobVO {id:324, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAB3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAABHBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 59778234354585, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Jan 16 10:51:42 CET 2015}, job origin:323
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.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.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2015-01-16 10:51:50,946 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Complete async job-324,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItNy1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6HQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-01-16 10:51:50,995 DEBUG [c.c.a.ApiServlet] (http-6443-exec-5:ctx-a7d8fbae
ctx-1bf279ff) ===END=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401893805
2015-01-16 10:51:51,040 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Done executing
com.cloud.vm.VmWorkStart for job-324
2015-01-16 10:51:51,110 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-9fe14da0 job-323 ctx-63724f41) Sync job-325 execution
on object VmWorkJobQueue.7
2015-01-16 10:51:51,114 WARN [c.c.u.d.Merovingian2]
(API-Job-Executor-8:ctx-9fe14da0 job-323 ctx-63724f41) Was unable to find lock
for the key vm_instance7 and thread id 539560830
2015-01-16 10:51:51,329 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Executing sync queue item:
SyncQueueItemVO {id:122, queueId: 38, contentType: AsyncJob, contentId: 325,
lastProcessMsid: 59778234354585, lastprocessNumber: 8, lastProcessTime: Fri Jan
16 10:51:51 CET 2015, created: Fri Jan 16 10:51:51 CET 2015}
2015-01-16 10:51:51,332 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Schedule queued job-325
2015-01-16 10:51:51,385 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Add job-325 into job
monitoring
2015-01-16 10:51:51,386 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Executing AsyncJobVO
{id:325, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAB3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 59778234354585, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Jan 16 10:51:51 CET 2015}
2015-01-16 10:51:51,386 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Run VM work job:
com.cloud.vm.VmWorkStart for VM 7, job origin: 323
2015-01-16 10:51:51,388 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Queue (queue id, sync type,
sync id) - (38,VmWorkJobQueue, 7) is reaching concurrency limit 1
2015-01-16 10:51:51,389 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) There is a pending process
in sync queue(id: 38)
2015-01-16 10:51:51,389 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Execute VM
work job:
com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":7,"handlerName":"VirtualMachineManagerImpl"}
2015-01-16 10:51:51,390 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-28:ctx-70811d27 job-323/job-324) Remove job-324 from job
monitoring
2015-01-16 10:51:51,405 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) VM state
transitted from :Stopped to Starting with event: StartRequestedvm's original
host id: 4 new host id: null host id before state transition: null
2015-01-16 10:51:51,405 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Successfully
transitioned to start state for VM[User|i-2-7-VM] reservation id =
ee5a8aca-0050-4492-b427-05afe5cb8944
2015-01-16 10:51:51,464 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Trying to
deploy VM, vm has dcId: 1 and podId: 1
2015-01-16 10:51:51,465 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Deploy avoids
pods: null, clusters: null, hosts: null
2015-01-16 10:51:51,472 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Root volume is
ready, need to place VM in volume's cluster
2015-01-16 10:51:51,472 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2)
Vol[8|vm=7|ROOT] is READY, changing deployment plan to use this pool's dcId: 1
, podId: 1 , and clusterId: 1
2015-01-16 10:51:51,493 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Deploy avoids
pods: [], clusters: [], hosts: []
2015-01-16 10:51:51,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2)
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner@18ee1aae
2015-01-16 10:51:51,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
1000, requested ram: 1073741824
2015-01-16 10:51:51,495 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Is ROOT volume
READY (pool already allocated)?: Yes
2015-01-16 10:51:51,496 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) This VM has
last host_id specified, trying to choose the same host: 4
2015-01-16 10:51:51,509 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Checking if
host: 4 has enough capacity for requested CPU: 1000 and requested RAM:
1073741824 , cpuOverprovisioningFactor: 1.0
2015-01-16 10:51:51,515 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Hosts's actual
total CPU: 57600 and CPU after applying overprovisioning: 57600
2015-01-16 10:51:51,515 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) We need to
allocate to the last host again, so checking if there is enough reserved
capacity
2015-01-16 10:51:51,515 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Reserved CPU:
0 , Requested CPU: 1000
2015-01-16 10:51:51,515 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Reserved RAM:
0 , Requested RAM: 1073741824
2015-01-16 10:51:51,516 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) STATS: Failed
to alloc resource from host: 4 reservedCpu: 0, requested cpu: 1000,
reservedMem: 0, requested mem: 1073741824
2015-01-16 10:51:51,516 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Host does not
have enough reserved CPU available, cannot allocate to this host.
2015-01-16 10:51:51,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) The last host
of this VM does not have enough capacity
2015-01-16 10:51:51,516 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Cannot choose
the last host to deploy this VM
2015-01-16 10:51:51,516 DEBUG [c.c.d.FirstFitPlanner]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Searching
resources only under specified Cluster: 1
2015-01-16 10:51:51,528 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Checking
resources in Cluster: 1 under Pod: 1
2015-01-16 10:51:51,528 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2015-01-16 10:51:51,535 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) FirstFitAllocator has 4 hosts to check for
allocation: [Host[-7-Routing], Host[-4-Routing], Host[-1-Routing],
Host[-6-Routing]]
2015-01-16 10:51:51,558 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Found 4 hosts for allocation after prioritization:
[Host[-7-Routing], Host[-4-Routing], Host[-1-Routing], Host[-6-Routing]]
2015-01-16 10:51:51,559 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024
2015-01-16 10:51:51,575 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host: 7 has cpu capability (cpu:24, speed:2400) to
support requested CPU: 1 and requested speed: 1000
2015-01-16 10:51:51,575 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Checking if host: 7 has enough capacity for requested
CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Hosts's actual total CPU: 57600 and CPU after
applying overprovisioning: 57600
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free CPU: 57600 , Requested CPU: 1000
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free RAM: 95574310912 , Requested RAM: 1073741824
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 7, used: 0, reserved:
0, actual total: 57600, total with overprovisioning: 57600; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-16 10:51:51,580 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 7, used: 0, reserved:
0, total: 95574310912; requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-16 10:51:51,581 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Found a suitable host, adding to list: 7
2015-01-16 10:51:51,596 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host: 4 has cpu capability (cpu:24, speed:2400) to
support requested CPU: 1 and requested speed: 1000
2015-01-16 10:51:51,596 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Checking if host: 4 has enough capacity for requested
CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-01-16 10:51:51,601 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Hosts's actual total CPU: 57600 and CPU after
applying overprovisioning: 57600
2015-01-16 10:51:51,601 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free CPU: 57600 , Requested CPU: 1000
2015-01-16 10:51:51,601 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free RAM: 95574310912 , Requested RAM: 1073741824
2015-01-16 10:51:51,601 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-01-16 10:51:51,602 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 4, used: 0, reserved:
0, actual total: 57600, total with overprovisioning: 57600; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-16 10:51:51,602 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 4, used: 0, reserved:
0, total: 95574310912; requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-16 10:51:51,602 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Found a suitable host, adding to list: 4
2015-01-16 10:51:51,617 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:24, speed:2400) to
support requested CPU: 1 and requested speed: 1000
2015-01-16 10:51:51,617 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested
CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-01-16 10:51:51,622 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Hosts's actual total CPU: 57600 and CPU after
applying overprovisioning: 57600
2015-01-16 10:51:51,622 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free CPU: 56100 , Requested CPU: 1000
2015-01-16 10:51:51,622 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free RAM: 93829480448 , Requested RAM: 1073741824
2015-01-16 10:51:51,622 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-01-16 10:51:51,622 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500,
reserved: 0, actual total: 57600, total with overprovisioning: 57600; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-16 10:51:51,623 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1744830464,
reserved: 0, total: 95574310912; requested mem:
1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-16 10:51:51,623 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Found a suitable host, adding to list: 1
2015-01-16 10:51:51,638 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host: 6 has cpu capability (cpu:24, speed:2400) to
support requested CPU: 1 and requested speed: 1000
2015-01-16 10:51:51,638 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Checking if host: 6 has enough capacity for requested
CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Hosts's actual total CPU: 57600 and CPU after
applying overprovisioning: 57600
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free CPU: 57600 , Requested CPU: 1000
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Free RAM: 95574310912 , Requested RAM: 1073741824
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host has enough CPU and RAM available
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 6, used: 0, reserved:
0, actual total: 57600, total with overprovisioning: 57600; requested
cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true
2015-01-16 10:51:51,643 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 6, used: 0, reserved:
0, total: 95574310912; requested mem: 1073741824,alloc_from_last_host?:false
,considerReservedCapacity?: true
2015-01-16 10:51:51,643 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Found a suitable host, adding to list: 6
2015-01-16 10:51:51,644 DEBUG [c.c.a.m.a.i.FirstFitAllocator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2
FirstFitRoutingAllocator) Host Allocator returning 4 suitable hosts
2015-01-16 10:51:51,646 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Checking
suitable pools for volume (Id, Type): (8,ROOT)
2015-01-16 10:51:51,647 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Volume has
pool already allocated, checking if pool can be reused, poolId: 1
2015-01-16 10:51:51,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Planner need
not allocate a pool for this volume since its READY
2015-01-16 10:51:51,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Trying to find
a potenial host and associated storage pools from the suitable host/pool lists
for this VM
2015-01-16 10:51:51,649 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Checking if
host: 7 can access any suitable storage pool for volume: ROOT
2015-01-16 10:51:51,652 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Host: 7 can
access pool: 1
2015-01-16 10:51:51,702 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Found a
potential host id: 7 name: SeSolXS03 and associated storage pools for this VM
2015-01-16 10:51:51,705 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) 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(7)-Storage()]
2015-01-16 10:51:51,705 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Deployment
found - P0=VM[User|i-2-7-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(7)-Storage()]
2015-01-16 10:51:51,795 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) VM state
transitted from :Starting to Starting with event: OperationRetryvm's original
host id: 4 new host id: 7 host id before state transition: null
2015-01-16 10:51:51,810 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Hosts's actual
total CPU: 57600 and CPU after applying overprovisioning: 57600
2015-01-16 10:51:51,810 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) We are
allocating VM, increasing the used capacity of this host:7
2015-01-16 10:51:51,810 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Current Used
CPU: 0 , Free CPU:57600 ,Requested CPU: 1000
2015-01-16 10:51:51,811 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Current Used
RAM: 0 , Free RAM:95574310912 ,Requested RAM: 1073741824
2015-01-16 10:51:51,811 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) CPU STATS
after allocation: for host: 7, old used: 0, old reserved: 0, actual total:
57600, total with overprovisioning: 57600; new used:1000, reserved:0; requested
cpu:1000,alloc_from_last:false
2015-01-16 10:51:51,811 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) RAM STATS
after allocation: for host: 7, old used: 0, old reserved: 0, total:
95574310912; new used: 1073741824, reserved: 0; requested mem:
1073741824,alloc_from_last:false
2015-01-16 10:51:51,859 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) VM is being
created in podId: 1
2015-01-16 10:51:51,865 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Network id=204
is already implemented
2015-01-16 10:51:52,119 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Service
SecurityGroup is not supported in the network id=204
2015-01-16 10:51:52,129 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Changing
active number of nics for network id=204 on 1
2015-01-16 10:51:52,263 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Asking
VirtualRouter to prepare for
Nic[17-7-ee5a8aca-0050-4492-b427-05afe5cb8944-10.1.1.56]
2015-01-16 10:51:52,285 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Lock is
acquired for network id 204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-01-16 10:51:52,290 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Lock is
released for network id 204 as a part of router startup in
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(7)-Storage()]
2015-01-16 10:51:52,306 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Service
SecurityGroup is not supported in the network id=204
2015-01-16 10:51:52,332 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Service
SecurityGroup is not supported in the network id=204
2015-01-16 10:51:52,342 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Applying dhcp
entry in network Ntwk[824dec2f-5a68-4caa-9097-c658b9119808|Guest|8]
2015-01-16 10:51:52,383 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
1-4700350636091244871: Sending { Cmd , MgmtId: 59778234354585, via:
1(SeSolXS01), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:36:8b:00:04","vmIpAddress":"10.1.1.56","vmName":"test2","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:36:8b:00:04","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"169.254.1.141","router.name":"r-4-VM"},"wait":0}}]
}
2015-01-16 10:51:52,383 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
1-4700350636091244871: Executing: { Cmd , MgmtId: 59778234354585, via:
1(SeSolXS01), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:36:8b:00:04","vmIpAddress":"10.1.1.56","vmName":"test2","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:36:8b:00:04","isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"10.1.1.1","router.ip":"169.254.1.141","router.name":"r-4-VM"},"wait":0}}]
}
2015-01-16 10:51:52,383 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-285:ctx-933610dc) Seq 1-4700350636091244871: Executing request
2015-01-16 10:51:52,384 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-285:ctx-933610dc) Executing command in VR:
/opt/cloud/bin/router_proxy.sh edithosts.sh 169.254.1.141 -m 02:00:36:8b:00:04
-4 10.1.1.56 -h test2 -d 10.1.1.1 -n 10.1.1.1
2015-01-16 10:51:53,914 DEBUG [c.c.a.ApiServlet]
(http-6443-exec-1:ctx-e82d6c66) ===START=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401896806
2015-01-16 10:51:53,994 DEBUG [c.c.a.ApiServlet] (http-6443-exec-1:ctx-e82d6c66
ctx-4e2216f5) ===END=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401896806
2015-01-16 10:51:56,938 DEBUG [c.c.a.ApiServlet]
(http-6443-exec-4:ctx-ceb477e0) ===START=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401899808
2015-01-16 10:51:57,010 DEBUG [c.c.a.ApiServlet] (http-6443-exec-4:ctx-ceb477e0
ctx-dd832f32) ===END=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401899808
2015-01-16 10:51:58,449 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 2-985: Processing Seq 2-985: { Cmd ,
MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-16 10:51:58,499 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) SeqA 2-985: Sending Seq 2-985: { Ans: , MgmtId:
59778234354585, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-16 10:51:59,684 ERROR [c.c.u.s.SshHelper]
(DirectAgent-285:ctx-933610dc) SSH execution of command
/opt/cloud/bin/router_proxy.sh edithosts.sh 169.254.1.141 -m 02:00:36:8b:00:04
-4 10.1.1.56 -h test2 -d 10.1.1.1 -n 10.1.1.1 has an error status code in
return. result output:
2015-01-16 10:51:59,686 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-285:ctx-933610dc) Seq 1-4700350636091244871: Response Received:
2015-01-16 10:51:59,686 DEBUG [c.c.a.t.Request] (DirectAgent-285:ctx-933610dc)
Seq 1-4700350636091244871: Processing: { Ans: , MgmtId: 59778234354585, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"","wait":0}}] }
2015-01-16 10:51:59,686 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
1-4700350636091244871: Received: { Ans: , MgmtId: 59778234354585, via: 1, Ver:
v1, Flags: 10, { Answer } }
2015-01-16 10:51:59,687 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Unable to
contact resource.
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
unreachable: Unable to apply dhcp entry on router
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:4018)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3134)
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
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy189.applyDhcpEntry(Unknown Source)
at
com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:905)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1221)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1343)
at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1279)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:986)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.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.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2015-01-16 10:51:59,735 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Cleaning up
resources for the vm VM[User|i-2-7-VM] in Starting state
2015-01-16 10:51:59,742 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
7-6269573631253151989: Sending { Cmd , MgmtId: 59778234354585, via:
7(SeSolXS03), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-7-VM","wait":0}}]
}
2015-01-16 10:51:59,743 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
7-6269573631253151989: Executing: { Cmd , MgmtId: 59778234354585, via:
7(SeSolXS03), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-7-VM","wait":0}}]
}
2015-01-16 10:51:59,743 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-72:ctx-7168af9c) Seq 7-6269573631253151989: Executing request
2015-01-16 10:51:59,755 INFO [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-72:ctx-7168af9c) VM does not exist on
XenServer3ecfaeea-fdf5-41ed-8cf8-b7fac961de03
2015-01-16 10:51:59,755 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-72:ctx-7168af9c) Seq 7-6269573631253151989: Response Received:
2015-01-16 10:51:59,756 DEBUG [c.c.a.t.Request] (DirectAgent-72:ctx-7168af9c)
Seq 7-6269573631253151989: Processing: { Ans: , MgmtId: 59778234354585, via:
7, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM does not
exist","wait":0}}] }
2015-01-16 10:51:59,756 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Seq
7-6269573631253151989: Received: { Ans: , MgmtId: 59778234354585, via: 7, Ver:
v1, Flags: 10, { StopAnswer } }
2015-01-16 10:51:59,771 DEBUG [c.c.n.NetworkModelImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Service
SecurityGroup is not supported in the network id=204
2015-01-16 10:51:59,775 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Changing
active number of nics for network id=204 on -1
2015-01-16 10:51:59,832 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Asking
VirtualRouter to release
NicProfile[17-7-ee5a8aca-0050-4492-b427-05afe5cb8944-10.1.1.56-null
2015-01-16 10:51:59,832 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Successfully
released network resources for the vm VM[User|i-2-7-VM]
2015-01-16 10:51:59,832 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Successfully
cleanued up resources for the vm VM[User|i-2-7-VM] in Starting state
2015-01-16 10:51:59,838 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Root volume is
ready, need to place VM in volume's cluster
2015-01-16 10:51:59,838 DEBUG [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2)
Vol[8|vm=7|ROOT] is READY, changing deployment plan to use this pool's dcId: 1
, podId: 1 , and clusterId: 1
2015-01-16 10:51:59,858 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Deploy avoids
pods: [], clusters: [], hosts: [7]
2015-01-16 10:51:59,859 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) DataCenter id
= '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM,
returning.
2015-01-16 10:51:59,879 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Deploy avoids
pods: [], clusters: [], hosts: [7]
2015-01-16 10:51:59,880 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) DataCenter id
= '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM,
returning.
2015-01-16 10:51:59,933 DEBUG [c.c.a.ApiServlet]
(http-6443-exec-3:ctx-db3d302c) ===START=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401902806
2015-01-16 10:51:59,993 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's original
host id: 4 new host id: null host id before state transition: 7
2015-01-16 10:52:00,005 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Hosts's actual
total CPU: 57600 and CPU after applying overprovisioning: 57600
2015-01-16 10:52:00,005 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Hosts's actual
total RAM: 95574311424 and RAM after applying overprovisioning: 95574310912
2015-01-16 10:52:00,005 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) release cpu
from host: 7, old used: 1000,reserved: 0, actual total: 57600, total with
overprovisioning: 57600; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2015-01-16 10:52:00,005 DEBUG [c.c.c.CapacityManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) release mem
from host: 7, old used: 1073741824,reserved: 0, total: 95574310912; new used:
0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2015-01-16 10:52:00,043 DEBUG [c.c.a.ApiServlet] (http-6443-exec-3:ctx-db3d302c
ctx-3000103a) ===END=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401902806
2015-01-16 10:52:00,150 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Invocation
exception, caused by: com.cloud.exception.InsufficientServerCapacityException:
Unable to create a deployment for VM[User|i-2-7-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-16 10:52:00,150 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325 ctx-5d673ee2) Rethrow
exception com.cloud.exception.InsufficientServerCapacityException: Unable to
create a deployment for VM[User|i-2-7-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
2015-01-16 10:52:00,151 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Done with run of VM work
job: com.cloud.vm.VmWorkStart for VM 7, job origin: 323
2015-01-16 10:52:00,151 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Unable to complete
AsyncJobVO {id:325, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAB3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 59778234354585, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Fri Jan 16 10:51:51 CET 2015}, job origin:323
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|i-2-7-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947)
at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.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.java:107)
at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2015-01-16 10:52:00,153 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Complete async job-325,
jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAT0pvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItNy1WTV11cgAeW0xqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnQ7AkYqPDz9IjkCAAB4cAAAAA1zcgAbamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50YQnFmiY23YUCAARJAApsaW5lTnVtYmVyTAAOZGVjbGFyaW5nQ2xhc3NxAH4ABEwACGZpbGVOYW1lcQB-AARMAAptZXRob2ROYW1lcQB-AAR4cAAAAHJ0ACBjb20uY2xvdWQudm0uVm1Xb3JrSm9iRGlzcGF0Y2hlcnQAGFZtV29ya0pvYkRpc3BhdGNoZXIuamF2YXQABnJ1bkpvYnNxAH4ACwAAAfd0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRzcQB-AAsAAAAxdAA-b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlJDF0ABtNYW5hZ2VkQ29udGV4dFJ1bm5hYmxlLmphdmF0AANydW5zcQB-AAsAAAA4dABCb3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5pbXBsLkRlZmF1bHRNYW5hZ2VkQ29udGV4dCQxdAAaRGVmYXVsdE1hbmFnZWRDb250ZXh0LmphdmF0AARjYWxsc3EAfgALAAAAZ3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AGnQAD2NhbGxXaXRoQ29udGV4dHNxAH4ACwAAADVxAH4AHXEAfgAadAAOcnVuV2l0aENvbnRleHRzcQB-AAsAAAAudAA8b3JnLmFwYWNoZS5jbG91ZHN0YWNrLm1hbmFnZWQuY29udGV4dC5NYW5hZ2VkQ29udGV4dFJ1bm5hYmxlcQB-ABZxAH4AF3NxAH4ACwAAAcxxAH4AEXEAfgAScQB-ABdzcQB-AAsAAAHXdAAuamF2YS51dGlsLmNvbmN1cnJlbnQuRXhlY3V0b3JzJFJ1bm5hYmxlQWRhcHRlcnQADkV4ZWN1dG9ycy5qYXZhcQB-ABtzcQB-AAsAAAEGdAAfamF2YS51dGlsLmNvbmN1cnJlbnQuRnV0dXJlVGFza3QAD0Z1dHVyZVRhc2suamF2YXEAfgAXc3EAfgALAAAEeXQAJ2phdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvcnQAF1RocmVhZFBvb2xFeGVjdXRvci5qYXZhdAAJcnVuV29ya2Vyc3EAfgALAAACZ3QALmphdmEudXRpbC5jb25jdXJyZW50LlRocmVhZFBvb2xFeGVjdXRvciRXb3JrZXJxAH4ALHEAfgAXc3EAfgALAAAC6HQAEGphdmEubGFuZy5UaHJlYWR0AAtUaHJlYWQuamF2YXEAfgAXc3IAJmphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVMaXN0_A8lMbXsjhACAAFMAARsaXN0cQB-AAZ4cgAsamF2YS51dGlsLkNvbGxlY3Rpb25zJFVubW9kaWZpYWJsZUNvbGxlY3Rpb24ZQgCAy173HgIAAUwAAWN0ABZMamF2YS91dGlsL0NvbGxlY3Rpb247eHBzcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhxAH4AOHg
2015-01-16 10:52:00,210 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Done executing
com.cloud.vm.VmWorkStart for job-325
2015-01-16 10:52:00,365 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Sync queue (38) is
currently empty
2015-01-16 10:52:00,367 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-29:ctx-790552b7 job-323/job-325) Remove job-325 from job
monitoring
2015-01-16 10:52:00,412 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-8:ctx-9fe14da0 job-323) Unexpected exception while executing
org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin
java.lang.RuntimeException: Job failed due to exception Unable to create a
deployment for VM[User|i-2-7-VM]
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:114)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
2015-01-16 10:52:00,413 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-9fe14da0 job-323) Complete async job-323, jobStatus:
FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Job
failed due to exception Unable to create a deployment for VM[User|i-2-7-VM]"}
2015-01-16 10:52:00,470 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-8:ctx-9fe14da0 job-323) Done executing
org.apache.cloudstack.api.command.admin.vm.StartVMCmdByAdmin for job-323
2015-01-16 10:52:00,514 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-8:ctx-9fe14da0 job-323) Remove job-323 from job monitoring
2015-01-16 10:52:00,636 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-055af142) Found 1 routers to update status.
2015-01-16 10:52:00,639 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-055af142) Found 0 networks to update RvR status.
2015-01-16 10:52:01,584 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-24b2f8d4) HostStatsCollector is running...
2015-01-16 10:52:01,603 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-284:ctx-fa7a74e3) Seq 1-4700350636091244872: Executing request
2015-01-16 10:52:01,625 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-284:ctx-fa7a74e3) Seq 1-4700350636091244872: Response Received:
2015-01-16 10:52:01,625 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-24b2f8d4)
Seq 1-4700350636091244872: Received: { Ans: , MgmtId: 59778234354585, via: 1,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-01-16 10:52:01,641 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-8c6740be) Seq 4-4532873024948404467: Executing request
2015-01-16 10:52:01,679 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-1:ctx-8c6740be) Seq 4-4532873024948404467: Response Received:
2015-01-16 10:52:01,679 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-24b2f8d4)
Seq 4-4532873024948404467: Received: { Ans: , MgmtId: 59778234354585, via: 4,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-01-16 10:52:01,694 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-143:ctx-91746cc7) Seq 6-2538904289930117371: Executing request
2015-01-16 10:52:01,732 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-143:ctx-91746cc7) Seq 6-2538904289930117371: Response Received:
2015-01-16 10:52:01,732 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-24b2f8d4)
Seq 6-2538904289930117371: Received: { Ans: , MgmtId: 59778234354585, via: 6,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-01-16 10:52:01,747 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-287:ctx-328750b9) Seq 7-6269573631253151990: Executing request
2015-01-16 10:52:01,780 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-287:ctx-328750b9) Seq 7-6269573631253151990: Response Received:
2015-01-16 10:52:01,780 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-24b2f8d4)
Seq 7-6269573631253151990: Received: { Ans: , MgmtId: 59778234354585, via: 7,
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2015-01-16 10:52:02,932 DEBUG [c.c.a.ApiServlet]
(http-6443-exec-2:ctx-25e83e71) ===START=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401905808
2015-01-16 10:52:03,012 DEBUG [c.c.a.ApiServlet] (http-6443-exec-2:ctx-25e83e71
ctx-d08ce6b6) ===END=== 115.114.134.114 -- GET
command=queryAsyncJobResult&jobId=cc59c0a1-1e6a-4771-9218-e9fbb09d27de&response=json&sessionkey=L%2B%2B9rTrruklJD5idAQ2JHDvf0XI%3D&_=1421401905808
2015-01-16 10:52:03,419 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) Ping from 43310
2015-01-16 10:52:03,450 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 2-986: Processing Seq 2-986: { Cmd ,
MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2015-01-16 10:52:03,518 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-4:null) SeqA 2-986: Sending Seq 2-986: { Ans: , MgmtId:
59778234354585, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-16 10:52:03,623 DEBUG [c.c.a.t.Request] (AgentManager-Handler-12:null)
Seq 0-0: Scheduling the first command { Cmd , MgmtId: -1, via: 0, Ver: v1,
Flags: 101,
[{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-5-VM-PremiumSecondaryStorageResource","name":"s-5-VM","id":0,"version":"4.4.1","iqn":"NoIqn","publicIpAddress":"188.95.36.130","publicNetmask":"255.255.255.248","publicMacAddress":"06:c2:c0:00:00:16","privateIpAddress":"172.16.5.211","privateMacAddress":"06:3d:ce:00:00:0c","privateNetmask":"255.255.255.0","storageIpAddress":"172.16.5.211","storageNetmask":"255.255.255.0","storageMacAddress":"06:3d:ce:00:00:0c","resourceName":"PremiumSecondaryStorageResource","wait":0}}]
}
2015-01-16 10:52:03,624 DEBUG [c.c.a.t.Request]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Seq 0-0: Processing the first command
{ Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 101,
[{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-5-VM-PremiumSecondaryStorageResource","name":"s-5-VM","id":0,"version":"4.4.1","iqn":"NoIqn","publicIpAddress":"188.95.36.130","publicNetmask":"255.255.255.248","publicMacAddress":"06:c2:c0:00:00:16","privateIpAddress":"172.16.5.211","privateMacAddress":"06:3d:ce:00:00:0c","privateNetmask":"255.255.255.0","storageIpAddress":"172.16.5.211","storageNetmask":"255.255.255.0","storageMacAddress":"06:3d:ce:00:00:0c","resourceName":"PremiumSecondaryStorageResource","wait":0}}]
}
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to BaremetalDhcpManagerImpl
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to BaremetalPxeManagerImpl
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to NetworkUsageManagerImpl
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to Ovs
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to PaloAltoExternalFirewallElement
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer
2015-01-16 10:52:03,630 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to F5ExternalLoadBalancerElement
2015-01-16 10:52:03,631 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to JuniperSRXExternalFirewallElement
2015-01-16 10:52:03,631 DEBUG [c.c.r.ResourceManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to PremiumSecondaryStorageManagerImpl
2015-01-16 10:52:03,633 DEBUG [c.c.u.d.T.Transaction]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Rolling back the transaction: Time = 2
Name = AgentConnectTaskPool-617; called by
-TransactionLegacy.rollback:900-TransactionLegacy.removeUpTo:843-TransactionLegacy.close:667-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.invoke:91-ReflectiveMethodInvocation.proceed:172-JdkDynamicAopProxy.invoke:204-$Proxy46.persist:-1-ResourceManagerImpl.createHostVO:1665-ResourceManagerImpl.createHostVOForConnectedAgent:1916-GeneratedMethodAccessor138.invoke:-1
2015-01-16 10:52:03,650 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Failed to handle host connection:
javax.persistence.EntityExistsException: Entity already exists:
2015-01-16 10:52:03,652 WARN [c.c.a.m.AgentManagerImpl]
(AgentConnectTaskPool-617:ctx-6c90a8a2) Unable to create attache for agent: Seq
0-0: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 101,
[{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-5-VM-PremiumSecondaryStorageResource","name":"s-5-VM","id":0,"version":"4.4.1","iqn":"NoIqn","publicIpAddress":"188.95.36.130","publicNetmask":"255.255.255.248","publicMacAddress":"06:c2:c0:00:00:16","privateIpAddress":"172.16.5.211","privateMacAddress":"06:3d:ce:00:00:0c","privateNetmask":"255.255.255.0","storageIpAddress":"172.16.5.211","storageNetmask":"255.255.255.0","storageMacAddress":"06:3d:ce:00:00:0c","resourceName":"PremiumSecondaryStorageResource","wait":0}}]
}
2015-01-16 10:52:03,838 WARN [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) Throwing away a request because it came through
as the first command on a connect: Seq 0--1: { Cmd , MgmtId: -1, via: 0, Ver:
v1, Flags: 111,
[{"com.cloud.agent.api.ShutdownCommand":{"reason":"sig.kill","wait":0}}] }
2015-01-16 10:52:03,839 WARN [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) Throwing away a request because it came through
as the first command on a connect: Seq 0-1: { Cmd , MgmtId: -1, via: 0, Ver:
v1, Flags: 11,
[{"com.cloud.agent.api.PingStorageCommand":{"changes":{},"hostType":"Storage","hostId":0,"wait":0}}]
}
^C
