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
