You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cloudstack.apache.org by Yitao Jiang <wi...@gmail.com> on 2014/03/19 12:23:36 UTC
Xenserver 6.2.0 CreateSnapshot weird error log
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
Re: Xenserver 6.2.0 CreateSnapshot weird error log
Posted by Yitao Jiang <wi...@gmail.com>.
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 <wi...@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 <wi...@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
>>
>
>
Re: Xenserver 6.2.0 CreateSnapshot weird error log
Posted by Yitao Jiang <wi...@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 <wi...@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
>