Hi, I figured it out.
Default vmsnapshot.create.wait value in global configuration is 1(s), and i don't know why the operation takes much more than 10 seconds,so i changed it to 60s. Now i can make vm snapshot. Thanks, Yitao 2014-03-20 9:33 GMT+08:00 Yitao Jiang <willier...@gmail.com>: > I can not make vm snapshot now . Do you guys know why ? > > Thanks, > > Yitao > > > 2014-03-19 19:23 GMT+08:00 Yitao Jiang <willier...@gmail.com>: > > Hi, stackers >> >> now i found a weird log happend in xenserver message log when creating a >> snapshot through cloudstack 4.2.1 web ui. >> And the task failed. >> Below are cloudstack log and log of xenserver >> >> management/catalina.out >> ============================================================= >> DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:) SeqA >> 3-30863: Processing Seq 3-30863: { Cmd , MgmtId: -1, via: 3, Ver: v1, >> Flags: 11, >> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n >> \"connections\": []\n}","wait":0}}] } >> DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:) SeqA >> 3-30863: Sending Seq 3-30863: { Ans: , MgmtId: 90520742010332, via: 3, >> Ver: v1, Flags: 100010, >> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Resetting >> hosts suitable for reconnect >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed >> resetting hosts suitable for reconnect >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Acquiring >> hosts for clusters already owned by this management server >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed >> acquiring hosts for clusters already owned by this management server >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Acquiring >> hosts for clusters not owned by any management server >> DEBUG [host.dao.HostDaoImpl] (ClusteredAgentManager Timer:) Completed >> acquiring hosts for clusters not owned by any management server >> DEBUG [cloud.server.StatsCollector] (StatsCollector-3:) StorageCollector >> is running... >> DEBUG [agent.transport.Request] (StatsCollector-3:) Seq 5-179437655: >> Received: { Ans: , MgmtId: 90520742010332, via: 5, Ver: v1, Flags: 10, { >> GetStorageStatsAnswer } } >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-90:) Seq >> 2-586154315: Executing request >> DEBUG [cloud.api.ApiServlet] (catalina-exec-18:) ===START=== >> 192.168.0.196 -- GET >> >> command=createVMSnapshot&virtualmachineid=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&snapshotmemory=true&name=snap001&description=snap001&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227086935 >> DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-18:) submit async >> job-522 = [ e2605931-6f40-46ea-8811-f769783ea45c ], details: AsyncJobVO >> {id:522, userId: 2, accountId: 2, sessionKey: null, instanceType: None, >> instanceId: 22, cmd: >> org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd, >> cmdOriginator: null, cmdInfo: >> {"sessionkey":"NSFhm8fl1Fp8K0U2s0Dn5xY5zhc\u003d","virtualmachineid":"ddf3a9b5-73f5-4b16-85b7-b110130ebf81","cmdEventType":"VMSNAPSHOT.CREATE","ctxUserId":"2","snapshotmemory":"true","httpmethod":"GET","response":"json","id":"22","description":"snap001","name":"snap001","_":"1395227086935","ctxAccountId":"2","ctxStartEventId":"2395"}, >> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, >> processStatus: 0, resultCode: 0, result: null, initMsid: 90520742010332, >> completeMsid: null, lastUpdated: null, lastPolled: null, created: null} >> DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Executing >> org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd for >> job-522 = [ e2605931-6f40-46ea-8811-f769783ea45c ] >> DEBUG [cloud.api.ApiServlet] (catalina-exec-18:) ===END=== 192.168.0.196 >> -- GET >> >> command=createVMSnapshot&virtualmachineid=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&snapshotmemory=true&name=snap001&description=snap001&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227086935 >> DEBUG [cloud.api.ApiServlet] (catalina-exec-22:) ===START=== >> 192.168.0.196 -- GET >> >> command=listZones&id=659ef764-c49d-4e01-bb71-1e13e6ef570e&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087375 >> DEBUG [cloud.api.ApiServlet] (catalina-exec-22:) ===END=== 192.168.0.196 >> -- GET >> >> command=listZones&id=659ef764-c49d-4e01-bb71-1e13e6ef570e&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087375 >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-90:) Seq >> 2-586154315: Response Received: >> DEBUG [agent.transport.Request] (StatsCollector-3:) Seq 2-586154315: >> Received: { Ans: , MgmtId: 90520742010332, via: 2, Ver: v1, Flags: 10, { >> GetStorageStatsAnswer } } >> DEBUG [cloud.api.ApiServlet] (catalina-exec-21:) ===START=== >> 192.168.0.196 -- GET >> >> command=listVirtualMachines&id=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087425 >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-490:) Seq >> 9-941424686: Executing request >> DEBUG [cloud.api.ApiServlet] (catalina-exec-21:) ===END=== 192.168.0.196 >> -- GET >> >> command=listVirtualMachines&id=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087425 >> DEBUG [cloud.api.ApiServlet] (catalina-exec-13:) ===START=== >> 192.168.0.196 -- GET >> >> command=listOsTypes&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087498 >> DEBUG [cloud.api.ApiServlet] (catalina-exec-23:) ===START=== >> 192.168.0.196 -- GET >> >> command=listTags&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&resourceId=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&resourceType=UserVm&listAll=true&_=1395227087518 >> DEBUG [cloud.api.ApiServlet] (catalina-exec-23:) ===END=== 192.168.0.196 >> -- GET >> >> command=listTags&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&resourceId=ddf3a9b5-73f5-4b16-85b7-b110130ebf81&resourceType=UserVm&listAll=true&_=1395227087518 >> DEBUG [agent.transport.Request] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Seq 9-941424687: Sending { Cmd >> , MgmtId: 90520742010332, via: 9, Ver: v1, Flags: 100011, >> [{"com.cloud.agent.api.CreateVMSnapshotCommand":{"vmState":"Running","volumeTOs":[{"id":104,"name":"ROOT-100","path":"756fc7d6-a420-43e8-a771-ee6961f41ee4","size":5368709120,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7bea0e75-0183-301b-9d72-db8d9ce7bec4","deviceId":0}],"target":{"id":22,"snapshotName":"i-2-100-VM_VS_20140319030456","type":"DiskAndMemory","current":false,"description":"snap001"},"vmName":"i-2-100-VM","guestOSType":"CentOS >> 6.2 (64-bit)","wait":1}}] } >> DEBUG [agent.transport.Request] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Seq 9-941424687: Executing: { >> Cmd , MgmtId: 90520742010332, via: 9, Ver: v1, Flags: 100011, >> [{"com.cloud.agent.api.CreateVMSnapshotCommand":{"vmState":"Running","volumeTOs":[{"id":104,"name":"ROOT-100","path":"756fc7d6-a420-43e8-a771-ee6961f41ee4","size":5368709120,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"7bea0e75-0183-301b-9d72-db8d9ce7bec4","deviceId":0}],"target":{"id":22,"snapshotName":"i-2-100-VM_VS_20140319030456","type":"DiskAndMemory","current":false,"description":"snap001"},"vmName":"i-2-100-VM","guestOSType":"CentOS >> 6.2 (64-bit)","wait":1}}] } >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-151:) Seq >> 9-941424687: Executing request >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-490:) Seq >> 9-941424686: Response Received: >> DEBUG [agent.transport.Request] (StatsCollector-3:) Seq 9-941424686: >> Received: { Ans: , MgmtId: 90520742010332, via: 9, Ver: v1, Flags: 10, { >> GetStorageStatsAnswer } } >> DEBUG [cloud.api.ApiServlet] (catalina-exec-13:) ===END=== >> 192.168.0.196 -- GET >> >> command=listOsTypes&response=json&sessionkey=NSFhm8fl1Fp8K0U2s0Dn5xY5zhc%3D&_=1395227087498 >> DEBUG [agent.manager.AgentAttache] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Seq 9-941424687: Waiting some >> more time because this is the current command >> WARN [xen.resource.CitrixResourceBase] (DirectAgent-151:) Async 1 >> seconds timeout for task com.xensource.xenapi.Task@d7fe271d >> ERROR [xen.resource.CitrixResourceBase] (DirectAgent-151:) Creating VM >> Snapshot i-2-100-VM_VS_20140319030456 failed due to: >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-151:) Seq >> 9-941424687: Response Received: >> DEBUG [agent.transport.Request] (DirectAgent-151:) Seq 9-941424687: >> Processing: { Ans: , MgmtId: 90520742010332, via: 9, Ver: v1, Flags: 10, >> [{"com.cloud.agent.api.CreateVMSnapshotAnswer":{"result":false,"details":"","wait":0}}] >> } >> DEBUG [agent.transport.Request] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Seq 9-941424687: Received: { >> Ans: , MgmtId: 90520742010332, via: 9, Ver: v1, Flags: 10, { >> CreateVMSnapshotAnswer } } >> ERROR [vm.snapshot.VMSnapshotManagerImpl] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Creating VM snapshot: >> i-2-100-VM_VS_20140319030456 failed due to >> DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:) SeqA >> 3-30864: Processing Seq 3-30864: { Cmd , MgmtId: -1, via: 3, Ver: v1, >> Flags: 11, >> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n >> \"connections\": []\n}","wait":0}}] } >> ERROR [vm.snapshot.VMSnapshotManagerImpl] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Create vm snapshot >> i-2-100-VM_VS_20140319030456 failed for vm: i-2-100-VM due to Creating VM >> snapshot: i-2-100-VM_VS_20140319030456 failed due to >> DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-5:) SeqA >> 3-30864: Sending Seq 3-30864: { Ans: , MgmtId: 90520742010332, via: 3, >> Ver: v1, Flags: 100010, >> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } >> ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Unexpected exception while >> executing >> org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd >> com.cloud.utils.exception.CloudRuntimeException: Creating VM snapshot: >> i-2-100-VM_VS_20140319030456 failed due to >> at >> com.cloud.vm.snapshot.VMSnapshotManagerImpl.createVmSnapshotInternal(VMSnapshotManagerImpl.java:406) >> at >> com.cloud.vm.snapshot.VMSnapshotManagerImpl.creatVMSnapshot(VMSnapshotManagerImpl.java:356) >> at >> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) >> at >> org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd.execute(CreateVMSnapshotCmd.java:100) >> 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:701) >> DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-23:job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ]) Complete async job-522 = [ >> e2605931-6f40-46ea-8811-f769783ea45c ], jobStatus: 2, resultCode: 530, >> result: Error Code: 530 Error text: Creating VM snapshot: >> i-2-100-VM_VS_20140319030456 failed due to >> DEBUG [cloud.server.StatsCollector] (StatsCollector-2:) VmStatsCollector >> is running... >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-365:) Seq >> 2-586154316: Executing request >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-365:) Vm cpu >> utilization 0.005625 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-365:) Vm cpu >> utilization 0.0046875 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-365:) Vm cpu >> utilization 0.0046875 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-365:) Vm cpu >> utilization 0.0065625 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-365:) Vm cpu >> utilization 0.4149999999999999 >> WARN [xen.resource.CitrixResourceBase] (DirectAgent-365:) Error while >> collecting disk stats from : >> You gave an invalid object reference. The object may have recently been >> deleted. The class parameter gives the type of reference given, and the >> handle parameter echoes the bad value given. >> at com.xensource.xenapi.Types.checkResponse(Types.java:209) >> at com.xensource.xenapi.Connection.dispatch(Connection.java:368) >> at >> com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909) >> at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:210) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStats(CitrixResourceBase.java:3087) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2973) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:514) >> at >> com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59) >> at >> com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106) >> at >> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186) >> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165) >> at >> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266) >> 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:701) >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-365:) Seq >> 2-586154316: Response Received: >> DEBUG [agent.transport.Request] (StatsCollector-2:) Seq 2-586154316: >> Received: { Ans: , MgmtId: 90520742010332, via: 2, Ver: v1, Flags: 10, { >> GetVmStatsAnswer } } >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-369:) Seq >> 9-941424688: Executing request >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-369:) Vm cpu >> utilization 0.004999999999999999 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-369:) Vm cpu >> utilization 0.005937499999999999 >> DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-369:) Vm cpu >> utilization 0.014374999999999999 >> WARN [xen.resource.CitrixResourceBase] (DirectAgent-369:) Error while >> collecting disk stats from : >> You gave an invalid object reference. The object may have recently been >> deleted. The class parameter gives the type of reference given, and the >> handle parameter echoes the bad value given. >> at com.xensource.xenapi.Types.checkResponse(Types.java:209) >> at com.xensource.xenapi.Connection.dispatch(Connection.java:368) >> at >> com.cloud.hypervisor.xen.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:909) >> at com.xensource.xenapi.VBDMetrics.getIoReadKbs(VBDMetrics.java:210) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.getVmStats(CitrixResourceBase.java:3087) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2973) >> at >> com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:514) >> at >> com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:59) >> at >> com.cloud.hypervisor.xen.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:106) >> at >> com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186) >> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165) >> at >> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266) >> 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:701) >> DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-369:) >> >> >> >> On xenserver 6.2.0 /var/log/messages >> =================================================== >> Mar 19 19:05:08 xenserver-02 xenopsd: >> [error|xenserver-02|9|events|xenops] Failed to read >> /vm/87f0bd84-b63d-685b-e3fa-a6bfd1299e1e/domains: has this domain already >> been cleaned up? >> Mar 19 19:05:08 xenserver-02 last message repeated 2 times >> Mar 19 19:05:08 xenserver-02 xapi: >> [error|xenserver-02|3472|Async.VM.checkpoint R:be264db3de5b|xenops] Caught >> exception suspending VM: Xenops_interface.Cancelled("103") >> Mar 19 19:05:08 xenserver-02 xapi: [ info|xenserver-02|236|xenops events >> D:10bca1451407|xenops] xenops: VM.remove >> 87f0bd84-b63d-685b-e3fa-a6bfd1299e1e >> Mar 19 19:05:08 xenserver-02 xenstored: A737 rm >> /vm/87f0bd84-b63d-685b-e3fa-a6bfd1299e1e >> Mar 19 19:05:08 xenserver-02 xenstored: A737 rm >> /vss/87f0bd84-b63d-685b-e3fa-a6bfd1299e1e >> Mar 19 19:05:08 xenserver-02 xenstored: A12 w event >> /vss/87f0bd84-b63d-685b-e3fa-a6bfd1299e1e vss >> Mar 19 19:05:08 xenserver-02 xapi: [ info|xenserver-02|3640 UNIX >> /var/xapi/xapi|session.logout D:c6464190b827|xapi] Session.destroy >> trackid=137986f4856f3a52319176585b51bd26 >> Mar 19 19:05:08 xenserver-02 xapi: [ info|xenserver-02|3641 UNIX >> /var/xapi/xapi|session.slave_login D:3224abab8217|xapi] Session.create >> trackid=ff1d7296152baa3ba237298571e8f977 pool=true uname= >> is_local_superuser=true auth_user_sid= >> parent=trackid=9834f5af41c964e225f24279aefe4e49 >> >> Thanks, >> >> Yitao >> > >