2013-12-20 22:54:31,599 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running...
2013-12-20 22:54:31,661 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-1722220572: Received:  { Ans: , MgmtId: 270567360573239, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 22:54:31,754 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-869400685: Received:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 22:54:31,833 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 1-869400686: Received:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2013-12-20 22:54:32,613 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START===  172.16.192.198 -- GET  command=queryAsyncJobResult&jobId=61584f9f-310e-44dd-b77c-8945fb6c2e9f&response=json&sessionkey=EL%2FnWwfFz%2FgW4oRonMuO1ZHEnxM%3D&_=1387580072593
2013-12-20 22:54:32,630 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END===  172.16.192.198 -- GET  command=queryAsyncJobResult&jobId=61584f9f-310e-44dd-b77c-8945fb6c2e9f&response=json&sessionkey=EL%2FnWwfFz%2FgW4oRonMuO1ZHEnxM%3D&_=1387580072593
2013-12-20 22:54:33,723 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 1-869400680: Processing:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b/65c62731-3415-4edd-916d-4dd5ffbd80c0","id":0}},"result":true,"wait":0}}] }
2013-12-20 22:54:33,723 DEBUG [agent.transport.Request] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Seq 1-869400680: Received:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 10, { CreateObjectAnswer } }
2013-12-20 22:54:33,755 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT
2013-12-20 22:54:33,791 DEBUG [agent.transport.Request] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Seq 1-869400687: Sending  { Cmd , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b/65c62731-3415-4edd-916d-4dd5ffbd80c0","volume":{"uuid":"12d127de-f4bb-4edf-b9e2-99771dc7bbb3","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e4bbff95-72f3-44eb-95ae-114ef8ac4d6c","id":2,"poolType":"SharedMountPoint","host":"localhost","path":"/mnt/165_cloudstack_nonha","port":0}},"name":"ROOT-12","size":21424504832,"path":"661437bb-25d5-4178-804d-0d15c097b26b","volumeId":15,"vmName":"i-2-12-VM","accountId":2,"format":"QCOW2","id":15,"hypervisorType":"KVM"},"parentSnapshotPath":"/mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b/82beb96e-1dcd-420a-a726-8da3f714da14","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e4bbff95-72f3-44eb-95ae-114ef8ac4d6c","id":2,"poolType":"SharedMountPoint","host":"localhost","path":"/mnt/165_cloudstack_nonha","port":0}},"vmName":"i-2-12-VM","name":"build_ROOT-12_20131220225259","hypervisorType":"KVM","id":11}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/15","volume":{"uuid":"12d127de-f4bb-4edf-b9e2-99771dc7bbb3","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e4bbff95-72f3-44eb-95ae-114ef8ac4d6c","id":2,"poolType":"SharedMountPoint","host":"localhost","path":"/mnt/165_cloudstack_nonha","port":0}},"name":"ROOT-12","size":21424504832,"path":"661437bb-25d5-4178-804d-0d15c097b26b","volumeId":15,"vmName":"i-2-12-VM","accountId":2,"format":"QCOW2","id":15,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://89.187.84.73/165_cloudstack_secondary","_role":"Image"}},"vmName":"i-2-12-VM","name":"build_ROOT-12_20131220225259","hypervisorType":"KVM","id":11}},"executeInSequence":true,"wait":21600}}] }
2013-12-20 22:54:34,109 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 1-869400687: Processing:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Failed to backup 65c62731-3415-4edd-916d-4dd5ffbd80c0 for disk /mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b to /mnt/6986a8e0-1339-354d-8903-6bf8a23f9874/snapshots/2/15","wait":0}}] }
2013-12-20 22:54:34,109 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-12:null) Seq 1-869400687: No more commands found
2013-12-20 22:54:34,109 DEBUG [agent.transport.Request] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Seq 1-869400687: Received:  { Ans: , MgmtId: 270567360573239, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2013-12-20 22:54:34,116 DEBUG [storage.snapshot.SnapshotManagerImpl] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Failed to create snapshot
com.cloud.utils.exception.CloudRuntimeException: Failed to backup 65c62731-3415-4edd-916d-4dd5ffbd80c0 for disk /mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b to /mnt/6986a8e0-1339-354d-8903-6bf8a23f9874/snapshots/2/15
	at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:280)
	at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:136)
	at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:279)
	at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1007)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1311)
	at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2773)
	at org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd.execute(CreateSnapshotCmd.java:170)
	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)
2013-12-20 22:54:34,124 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Take snapshot: 15 failed
com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot
	at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1034)
	at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
	at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1311)
	at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2773)
	at org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd.execute(CreateSnapshotCmd.java:170)
	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)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to backup 65c62731-3415-4edd-916d-4dd5ffbd80c0 for disk /mnt/165_cloudstack_nonha/661437bb-25d5-4178-804d-0d15c097b26b to /mnt/6986a8e0-1339-354d-8903-6bf8a23f9874/snapshots/2/15
	at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:280)
	at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:136)
	at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:279)
	at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1007)
	... 16 more
2013-12-20 22:54:34,124 DEBUG [user.snapshot.CreateSnapshotCmd] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Failed to create snapshot
org.apache.cloudstack.api.ServerApiException
	at org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd.execute(CreateSnapshotCmd.java:176)
	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)
2013-12-20 22:54:34,125 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-4:job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ]) Complete async job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Failed to create snapshot due to an internal error creating snapshot for volume 15
2013-12-20 22:54:35,318 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 5-205: Processing Seq 5-205:  { Cmd , MgmtId: -1, via: 5, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":4,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2013-12-20 22:54:35,321 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) SeqA 5-205: Sending Seq 5-205:  { Ans: , MgmtId: 270567360573239, via: 5, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-12-20 22:54:35,614 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START===  172.16.192.198 -- GET  command=queryAsyncJobResult&jobId=61584f9f-310e-44dd-b77c-8945fb6c2e9f&response=json&sessionkey=EL%2FnWwfFz%2FgW4oRonMuO1ZHEnxM%3D&_=1387580075593
2013-12-20 22:54:35,625 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-16:null) Async job-69 = [ 61584f9f-310e-44dd-b77c-8945fb6c2e9f ] completed
2013-12-20 22:54:35,629 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END===  172.16.192.198 -- GET  command=queryAsyncJobResult&jobId=61584f9f-310e-44dd-b77c-8945fb6c2e9f&response=json&sessionkey=EL%2FnWwfFz%2FgW4oRonMuO1ZHEnxM%3D&_=1387580075593