You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Bjoern Teipel <bj...@internetbrands.com> on 2013/10/21 22:24:46 UTC
4.2.1-snapshot : com.cloud.exception.InsufficientServerCapacityException:
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
Re: 4.2.1-snapshot : com.cloud.exception.InsufficientServerCapacityException:
Posted by Bjoern Teipel <bj...@internetbrands.com>.
Damn, I guess I found the issue.
The JDBC error bothered me that much that I looked into my DB config and
then I knew what happened.
The wait_timeout is set to 30 seconds, so during the write of the qcow
snapshot file to the secondary storage, the mysql session was terminated.
After the copy was done, cloudstack tried to select/update tables on a
non existing session anymore.
I removed now this parameter and wait_timeout is set to 8h, the standard
value. So at least all backups should work within this period.
Probably the db/or snapshot code in cloudstack should be changed a
little bit to check for a connection before writing to the DB.
Or even better it should just close the connection and let the copy
finish and then reopen a new connection. On large volumes the copy could
take significant amount of time and I don't want to deal with
wait_timeout all time
Bjoern
On 10/23/2013 12:04 AM, Bjoern Teipel wrote:
> Yes I had and I changed the delay to 1h.
> I also got link communication failures and the secondary storage was
> stuck during this time so I decided to rebuild the zone and change the
> NFS storage from Gluster to a standard NFS server removing the
> iptables rules etc. But I'm still rebuilding it and testing right now
> KVM with openvswitch though ...
>
> Bjoern
>
> On 10/22/2013 11:54 PM, Whyspirit wrote:
>> 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
>> <bj...@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
>>>
>>>
>>>
>>
>>
>>
>
Re: 4.2.1-snapshot : com.cloud.exception.InsufficientServerCapacityException:
Posted by Bjoern Teipel <bj...@internetbrands.com>.
Yes I had and I changed the delay to 1h.
I also got link communication failures and the secondary storage was
stuck during this time so I decided to rebuild the zone and change the
NFS storage from Gluster to a standard NFS server removing the iptables
rules etc. But I'm still rebuilding it and testing right now KVM with
openvswitch though ...
Bjoern
On 10/22/2013 11:54 PM, Whyspirit wrote:
> 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
> <bj...@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
>>
>>
>>
>
>
>
Re: 4.2.1-snapshot : com.cloud.exception.InsufficientServerCapacityException:
Posted by Whyspirit <wh...@netcourrier.com>.
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
<bj...@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
>
>
>