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
