2014-01-01 19:56:52,485 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===START=== 172.16.211.140 -- GET command=createSnapshot&volumeid=41b501e6-c38c-4d09-b15a-776bc26fa0da&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606212440 2014-01-01 19:56:52,934 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-24:null) submit async job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ], details: AsyncJobVO {id:19, userId: 2, accountId: 2, sessionKey: null, instanceType: Snapshot, instanceId: 1, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdOriginator: null, cmdInfo: {"id":"1","response":"json","sessionkey":"TCV9p2Bdw9X9/FxKrNEdgLf6EnU\u003d","cmdEventType":"SNAPSHOT.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1388606212440","volumeid":"41b501e6-c38c-4d09-b15a-776bc26fa0da","ctxAccountId":"2","ctxStartEventId":"84"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 279278805450791, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2014-01-01 19:56:52,936 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null) ===END=== 172.16.211.140 -- GET command=createSnapshot&volumeid=41b501e6-c38c-4d09-b15a-776bc26fa0da&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606212440 2014-01-01 19:56:52,937 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ] 2014-01-01 19:56:52,977 INFO [user.snapshot.CreateSnapshotCmd] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) VOLSS: createSnapshotCmd starts:1388606212977 2014-01-01 19:56:53,397 DEBUG [agent.transport.Request] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Seq 1-2045837344: Sending { Cmd , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"41b501e6-c38c-4d09-b15a-776bc26fa0da","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0","id":1,"poolType":"NetworkFilesystem","host":"172.16.203.68","path":"/primary","port":2049}},"name":"ROOT-11","size":8589934592,"path":"41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20","volumeId":7,"vmName":"i-2-11-VM","accountId":2,"format":"QCOW2","id":7,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0","id":1,"poolType":"NetworkFilesystem","host":"172.16.203.68","path":"/primary","port":2049}},"vmName":"i-2-11-VM","name":"asf_ROOT-11_20140101195652","hypervisorType":"KVM","id":1}},"wait":0}}] } 2014-01-01 19:56:53,855 DEBUG [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Detected management node left, id:2, nodeIP:172.16.203.68 2014-01-01 19:56:53,855 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Trying to connect to 172.16.203.68 2014-01-01 19:56:53,856 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Management node 2 is detected inactive by timestamp but is pingable 2014-01-01 19:56:53,891 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-289: Processing Seq 3-289: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-01-01 19:56:53,978 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 3-289: Sending Seq 3-289: { Ans: , MgmtId: 279278805450791, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-01-01 19:56:55,897 DEBUG [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Detected management node left, id:2, nodeIP:172.16.203.68 2014-01-01 19:56:55,898 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Trying to connect to 172.16.203.68 2014-01-01 19:56:55,898 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Management node 2 is detected inactive by timestamp but is pingable 2014-01-01 19:56:55,904 DEBUG [agent.transport.Request] (AgentManager-Handler-5:null) Seq 1-2045837344: Processing: { Ans: , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0/41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20/fdae7a7e-1002-4ebe-b502-393fa0064966","id":0}},"result":true,"wait":0}}] } 2014-01-01 19:56:55,905 DEBUG [agent.transport.Request] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Seq 1-2045837344: Received: { Ans: , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 10, { CreateObjectAnswer } } 2014-01-01 19:56:55,974 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===START=== 172.16.211.140 -- GET command=queryAsyncJobResult&jobId=90b6a4d7-997d-4b37-865a-a9df8cf117f8&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606215955 2014-01-01 19:56:56,185 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null) ===END=== 172.16.211.140 -- GET command=queryAsyncJobResult&jobId=90b6a4d7-997d-4b37-865a-a9df8cf117f8&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606215955 2014-01-01 19:56:56,651 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT 2014-01-01 19:56:56,710 DEBUG [agent.transport.Request] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Seq 1-2045837345: Sending { Cmd , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0/41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20/fdae7a7e-1002-4ebe-b502-393fa0064966","volume":{"uuid":"41b501e6-c38c-4d09-b15a-776bc26fa0da","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0","id":1,"poolType":"NetworkFilesystem","host":"172.16.203.68","path":"/primary","port":2049}},"name":"ROOT-11","size":8589934592,"path":"41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20","volumeId":7,"vmName":"i-2-11-VM","accountId":2,"format":"QCOW2","id":7,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0","id":1,"poolType":"NetworkFilesystem","host":"172.16.203.68","path":"/primary","port":2049}},"vmName":"i-2-11-VM","name":"asf_ROOT-11_20140101195652","hypervisorType":"KVM","id":1}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/7","volume":{"uuid":"41b501e6-c38c-4d09-b15a-776bc26fa0da","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0","id":1,"poolType":"NetworkFilesystem","host":"172.16.203.68","path":"/primary","port":2049}},"name":"ROOT-11","size":8589934592,"path":"41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20","volumeId":7,"vmName":"i-2-11-VM","accountId":2,"format":"QCOW2","id":7,"hypervisorType":"KVM"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://172.16.203.68/secondary","_role":"Image"}},"vmName":"i-2-11-VM","name":"asf_ROOT-11_20140101195652","hypervisorType":"KVM","id":1}},"executeInSequence":true,"wait":21600}}] } 2014-01-01 19:56:56,959 DEBUG [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Detected management node left, id:2, nodeIP:172.16.203.68 2014-01-01 19:56:56,959 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Trying to connect to 172.16.203.68 2014-01-01 19:56:56,960 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Management node 2 is detected inactive by timestamp but is pingable 2014-01-01 19:56:57,142 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 1-2045837345: Processing: { Ans: , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Failed to backup fdae7a7e-1002-4ebe-b502-393fa0064966 for disk /mnt/1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0/41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20 to /mnt/4ee97827-2a63-338a-928c-b57249ba76fc/snapshots/2/7","wait":0}}] } 2014-01-01 19:56:57,142 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 1-2045837345: No more commands found 2014-01-01 19:56:57,143 DEBUG [agent.transport.Request] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Seq 1-2045837345: Received: { Ans: , MgmtId: 279278805450791, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } } 2014-01-01 19:56:57,386 DEBUG [storage.snapshot.SnapshotManagerImpl] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Failed to create snapshot com.cloud.utils.exception.CloudRuntimeException: Failed to backup fdae7a7e-1002-4ebe-b502-393fa0064966 for disk /mnt/1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0/41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20 to /mnt/4ee97827-2a63-338a-928c-b57249ba76fc/snapshots/2/7 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) 2014-01-01 19:56:57,553 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Take snapshot: 7 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 fdae7a7e-1002-4ebe-b502-393fa0064966 for disk /mnt/1ffa7f05-a7d8-3f0c-be6b-cb05a2e005b0/41d6ed5c-bbc1-4d40-8ecc-5a7357e00e20 to /mnt/4ee97827-2a63-338a-928c-b57249ba76fc/snapshots/2/7 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 2014-01-01 19:56:57,554 DEBUG [user.snapshot.CreateSnapshotCmd] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) 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) 2014-01-01 19:56:57,556 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-4:job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ]) Complete async job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Failed to create snapshot due to an internal error creating snapshot for volume 7 2014-01-01 19:56:58,338 DEBUG [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Detected management node left, id:2, nodeIP:172.16.203.68 2014-01-01 19:56:58,338 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Trying to connect to 172.16.203.68 2014-01-01 19:56:58,339 INFO [cloud.cluster.ClusterManagerImpl] (Cluster-Heartbeat-1:null) Management node 2 is detected inactive by timestamp but is pingable 2014-01-01 19:56:58,892 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-290: Processing Seq 3-290: { Cmd , MgmtId: -1, via: 3, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-01-01 19:56:58,968 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===START=== 172.16.211.140 -- GET command=queryAsyncJobResult&jobId=90b6a4d7-997d-4b37-865a-a9df8cf117f8&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606218954 2014-01-01 19:56:58,979 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-6:null) SeqA 3-290: Sending Seq 3-290: { Ans: , MgmtId: 279278805450791, via: 3, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] } 2014-01-01 19:56:58,981 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-2:null) Async job-19 = [ 90b6a4d7-997d-4b37-865a-a9df8cf117f8 ] completed 2014-01-01 19:56:58,987 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null) ===END=== 172.16.211.140 -- GET command=queryAsyncJobResult&jobId=90b6a4d7-997d-4b37-865a-a9df8cf117f8&response=json&sessionkey=TCV9p2Bdw9X9%2FFxKrNEdgLf6EnU%3D&_=1388606218954