Hello. Do you have any VMs that needs to be expunged. If it is the case,
please reduce number of them by changing parameters in cloudstack UI
(reduce expunge.delay and expunge. Interval).
Envoyé avec AquaMail pour Android
http://www.aqua-mail.com
Le 21 octobre 2013 22:24:46 Bjoern Teipel
<bjoern.tei...@internetbrands.com> a écrit :
Hi,
my cstk deployment stopped working and I can't figure out why, because all
capacity related metrics are ok.
2013-10-21 13:17:51,412 INFO [user.vm.DeployVMCmd] (Job-Executor-8:job-126
= [ fed97281-7904-427c-b450-80fb32210cbc ])
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for
VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]Scope=interface
com.cloud.dc.DataCenter; id=1
2013-10-21 13:17:51,412 INFO [user.vm.DeployVMCmd] (Job-Executor-8:job-126
= [ fed97281-7904-427c-b450-80fb32210cbc ]) Unable to create a deployment
for VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]Scope=interface
com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:841)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:237)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3404)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2964)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2950)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-10-21 13:17:51,413 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Complete async job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ], jobStatus: 2
, resultCode: 530, result: Error Code: 533 Error text: Unable to create a
deployment for VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]
but this is what I saw before this error:
2013-10-21 13:17:50,617 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2013-10-21 13:17:50,620 INFO [storage.endpoint.DefaultEndPointSelector]
(StatsCollector-1:null) No running ssvm is found, so command will be sent
to LocalHostEndPoint
2013-10-21 13:17:50,674 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 1-531890650: Received: { Ans: , MgmtId:
110493122496, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-10-21 13:17:50,946 DEBUG [agent.transport.Request]
(StatsCollector-1:null) Seq 1-531890651: Received: { Ans: , MgmtId:
110493122496, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-10-21 13:17:51,142 DEBUG [agent.transport.Request]
(AgentManager-Handler-15:null) Seq 1-531890647: Processing: { Ans: ,
MgmtId: 110493122496, via: 1, Ver: v1, Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"3000605a-b528-400c-8ff2-a894c20b0705","id":0,"format":"QCOW2","accountId":0,"hvm":false}},"result":true,"wait":0}}]
}
2013-10-21 13:17:51,142 DEBUG [agent.transport.Request]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Seq
1-531890647: Received: { Ans: , MgmtId: 110493122496, via: 1, Ver: v1,
Flags: 110, { CopyCmdAnswer } }
2013-10-21 13:17:51,142 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-15:null) Seq 1-531890647: No more commands found
2013-10-21 13:17:51,143 DEBUG [image.store.TemplateObject]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) failed
to process event and answer
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@5cdcbeb5: SELECT
template_spool_ref.id, template_spool_ref.pool_id,
template_spool_ref.template_id, template_spool_ref.created,
template_spool_ref.last_updated, template_spool_ref.download_pct,
template_spool_ref.download_state, template_spool_ref.local_path,
template_spool_ref.error_str, template_spool_ref.job_id,
template_spool_ref.install_path, template_spool_ref.template_size,
template_spool_ref.marked_for_gc, template_spool_ref.update_count,
template_spool_ref.updated, template_spool_ref.state FROM
template_spool_ref WHERE template_spool_ref.pool_id = 2 AND
template_spool_ref.template_id = 209 ORDER BY RAND() LIMIT 1
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:414)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:349)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.utils.db.GenericDaoBase.findOneIncludingRemovedBy(GenericDaoBase.java:859)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.storage.dao.VMTemplatePoolDaoImpl.findByPoolTemplate(VMTemplatePoolDaoImpl.java:128)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.storage.image.store.TemplateObject.processEvent(TemplateObject.java:182)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyBaseImageCallback(VolumeServiceImpl.java:478)
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:616)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
at
org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:423)
at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:58)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:446)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:575)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2567)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2631)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3404)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2964)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2950)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure
The last packet successfully received from the server was 35,117
milliseconds ago. The last packet sent successfully to the server was 1
milliseconds ago.
at
sun.reflect.GeneratedConstructorAccessor149.newInstance(Unknown Source)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3567)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2318)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:408)
... 59 more
Caused by: java.io.EOFException: Can not read response from server.
Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
... 74 more
2013-10-21 13:17:51,153 DEBUG [storage.volume.VolumeServiceImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) failed
to create template on storage
java.lang.RuntimeException: InvocationTargetException when invoking RPC
callback for command: copyBaseImageCallback
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:26)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:120)
at
org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:423)
at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:58)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:446)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:575)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2567)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2631)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3404)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2964)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2950)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.lang.reflect.InvocationTargetException
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:616)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:142)
... 29 more
Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to
process event
at
org.apache.cloudstack.storage.image.store.TemplateObject.processEvent(TemplateObject.java:226)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyBaseImageCallback(VolumeServiceImpl.java:478)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
... 33 more
Caused by: com.cloud.utils.exception.CloudRuntimeException: DB Exception
on: com.mysql.jdbc.JDBC4PreparedStatement@5cdcbeb5: SELECT
template_spool_ref.id, template_spool_ref.pool_id,
template_spool_ref.template_id, template_spool_ref.created,
template_spool_ref.last_updated, template_spool_ref.download_pct,
template_spool_ref.download_state, template_spool_ref.local_path,
template_spool_ref.error_str, template_spool_ref.job_id,
template_spool_ref.install_path, template_spool_ref.template_size,
template_spool_ref.marked_for_gc, template_spool_ref.update_count,
template_spool_ref.updated, template_spool_ref.state FROM
template_spool_ref WHERE template_spool_ref.pool_id = 2 AND
template_spool_ref.template_id = 209 ORDER BY RAND() LIMIT 1
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:414)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:349)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.utils.db.GenericDaoBase.findOneIncludingRemovedBy(GenericDaoBase.java:859)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.storage.dao.VMTemplatePoolDaoImpl.findByPoolTemplate(VMTemplatePoolDaoImpl.java:128)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.storage.image.store.TemplateObject.processEvent(TemplateObject.java:182)
... 35 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure
The last packet successfully received from the server was 35,117
milliseconds ago. The last packet sent successfully to the server was 1
milliseconds ago.
at
sun.reflect.GeneratedConstructorAccessor149.newInstance(Unknown Source)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3567)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2318)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at
com.cloud.utils.db.GenericDaoBase.searchIncludingRemoved(GenericDaoBase.java:408)
... 59 more
Caused by: java.io.EOFException: Can not read response from server.
Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
... 74 more
2013-10-21 13:17:51,156 WARN
[storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-8:job-126 =
[ fed97281-7904-427c-b450-80fb32210cbc ]) Template 209 is not found on
storage pool 2, so no need to delete
2013-10-21 13:17:51,157 INFO [storage.volume.VolumeServiceImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
releasing lock for VMTemplateStoragePool 9
2013-10-21 13:17:51,157 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Failed
to start instance VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]
com.cloud.utils.exception.CloudRuntimeException: can't find mapping in
ObjectInDataStore table for:
org.apache.cloudstack.storage.image.store.TemplateObject@616b3665
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:293)
at
org.apache.cloudstack.storage.image.store.TemplateObject.processEvent(TemplateObject.java:162)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:449)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:575)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2567)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2631)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:888)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:577)
at
org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:227)
at
org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3404)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2964)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2950)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-10-21 13:17:51,160 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Cleaning up resources for the vm
VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a] in Starting state
2013-10-21 13:17:51,161 DEBUG [agent.transport.Request]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Seq
1-531890652: Sending { Cmd , MgmtId: 110493122496, via: 1, Ver: v1, Flags:
100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-3-23-VM","wait":0}}]
}
2013-10-21 13:17:51,308 DEBUG [agent.transport.Request]
(AgentManager-Handler-1:null) Seq 1-531890652: Processing: { Ans: ,
MgmtId: 110493122496, via: 1, Ver: v1, Flags: 110,
[{"com.cloud.agent.api.StopAnswer":{"vncPort":0,"result":true,"wait":0}}] }
2013-10-21 13:17:51,308 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-1:null) Seq 1-531890652: No more commands found
2013-10-21 13:17:51,308 DEBUG [agent.transport.Request]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Seq
1-531890652: Received: { Ans: , MgmtId: 110493122496, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2013-10-21 13:17:51,308 DEBUG [cloud.api.ApiServlet]
(catalina-exec-23:null) ===START=== 172.16.7.249 -- GET
command=queryAsyncJobResult&jobId=fed97281-7904-427c-b450-80fb32210cbc&response=json&sessionkey=F4HGUE031dGxlvEQUFnGYGQT6ZI%3D&_=1382386671305
2013-10-21 13:17:51,319 DEBUG [cloud.network.NetworkModelImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Service
SecurityGroup is not supported in the network id=210
2013-10-21 13:17:51,322 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Changing active number of nics for network id=210 on -1
2013-10-21 13:17:51,326 DEBUG [cloud.api.ApiServlet]
(catalina-exec-23:null) ===END=== 172.16.7.249 -- GET
command=queryAsyncJobResult&jobId=fed97281-7904-427c-b450-80fb32210cbc&response=json&sessionkey=F4HGUE031dGxlvEQUFnGYGQT6ZI%3D&_=1382386671305
2013-10-21 13:17:51,328 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Asking
VirtualRouter to release
Nic[46-23-88b03bb7-eb52-4d02-a24b-37f5aac4669b-10.1.1.249]
2013-10-21 13:17:51,329 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Successfully released network resources for the vm
VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a]
2013-10-21 13:17:51,329 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Successfully cleanued up resources for the vm
VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a] in Starting state
2013-10-21 13:17:51,332 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) 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
2013-10-21 13:17:51,338 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Hosts's
actual total CPU: 42544 and CPU after applying overprovisioning: 42544
2013-10-21 13:17:51,338 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Hosts's
actual total RAM: 126843064320 and RAM after applying overprovisioning:
126843060224
2013-10-21 13:17:51,338 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) release
cpu from host: 1, old used: 6000,reserved: 0, actual total: 42544, total
with overprovisioning: 42544; new used: 5500,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2013-10-21 13:17:51,338 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) release
mem from host: 1, old used: 4160749568,reserved: 0, total: 126843060224;
new used: 3623878656,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-10-21 13:17:51,349 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) VM
state transitted from :Stopped to Starting with event: StartRequestedvm's
original host id: null new host id: null host id before state transition: null
2013-10-21 13:17:51,349 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Successfully transitioned to start state for
VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a] reservation id =
6fe9aa6f-30f4-455b-9196-39b96ace239f
2013-10-21 13:17:51,351 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Trying
to deploy VM, vm has dcId: 1 and podId: 1
2013-10-21 13:17:51,351 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Deploy
avoids pods: [], clusters: [], hosts: [1]
2013-10-21 13:17:51,357 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Deploy
avoids pods: [], clusters: [], hosts: [1]
2013-10-21 13:17:51,358 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_26f423f7@1d892dc8
2013-10-21 13:17:51,358 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Trying
to allocate a host and storage pools from dc:1, pod:1,cluster:null,
requested cpu: 500, requested ram: 536870912
2013-10-21 13:17:51,358 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Is ROOT
volume READY (pool already allocated)?: No
2013-10-21 13:17:51,358 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Searching resources only under specified Pod: 1
2013-10-21 13:17:51,358 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 1
2013-10-21 13:17:51,361 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Removing from the clusterId list these clusters from avoid set: []
2013-10-21 13:17:51,366 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Checking resources in Cluster: 1 under Pod: 1
2013-10-21 13:17:51,366 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1
2013-10-21 13:17:51,368 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for
allocation: [Host[-1-Routing]]
2013-10-21 13:17:51,370 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) Found 1 hosts for allocation after
prioritization: [Host[-1-Routing]]
2013-10-21 13:17:51,370 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) Looking for speed=500Mhz, Ram=512
2013-10-21 13:17:51,370 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) Host name: hq-kvmhv-002.internetbrands.com,
hostId: 1 is in avoid set, skipping this and trying other available hosts
2013-10-21 13:17:51,370 DEBUG [allocator.impl.FirstFitAllocator]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]
FirstFitRoutingAllocator) Host Allocator returning 0 suitable hosts
2013-10-21 13:17:51,370 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) No
suitable hosts found
2013-10-21 13:17:51,370 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) No
suitable hosts found under this Cluster: 1
2013-10-21 13:17:51,372 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Could
not find suitable Deployment Destination for this VM under any clusters,
returning.
2013-10-21 13:17:51,372 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Searching resources only under specified Pod: 1
2013-10-21 13:17:51,372 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) Listing
clusters in order of aggregate capacity, that have (atleast one host with)
enough CPU and RAM capacity under this Pod: 1
2013-10-21 13:17:51,374 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Removing from the clusterId list these clusters from avoid set: [1]
2013-10-21 13:17:51,374 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) No
clusters found after removing disabled clusters and clusters in avoid list,
returning.
2013-10-21 13:17:51,378 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ]) VM
state transitted from :Starting to Stopped with event: OperationFailedvm's
original host id: null new host id: null host id before state transition: null
2013-10-21 13:17:51,386 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-8:job-126 = [ fed97281-7904-427c-b450-80fb32210cbc ])
Destroying vm VM[User|d0bc4ffd-7850-4503-a62b-482895b4b08a] as it failed to
create on Host with Id:null
