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
>
