cloudstack-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bjoern Teipel <bjoern.tei...@internetbrands.com>
Subject Re: 4.2.1-snapshot : com.cloud.exception.InsufficientServerCapacityException:
Date Fri, 25 Oct 2013 08:24:46 GMT
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 
>> <bjoern.teipel@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
>>>
>>>
>>>
>>
>>
>>
>


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message