Details
Description
Creating snaphot fails hanging with state CreatedOnPrimary. Sometimes creating snaphot is successful.
Snapshot logical volume is created and not deleted.
When running snaphot with only single host snapshot is created normaly. Guess snapshot backup is trying access snapshot LV from host on which snapshot LV is not opened.
Here is management log:
2013-10-18 17:32:58,512 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-10:null) submit async job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ], details: AsyncJobVO {id:41, userId: 2, accountId: 2, sessionKey: null, instanceType: Snapshot, instanceId: 10, cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdOriginator: null, cmdInfo:
{"id":"10","response":"json","sessionkey":"HKb50xNHyZm2wJx/IHi5S7UWBGQ\u003d","cmdEventType":"SNAPSHOT.CREATE","ctxUserId":"2","httpmethod":"GET","_":"1382106777170","volumeid":"560a9f6e-9864-43cc-8096-ed9cd6c97311","ctxAccountId":"2","ctxStartEventId":"126"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 161342718518, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-10-18 17:32:58,514 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Executing org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]
2013-10-18 17:32:58,549 INFO [user.snapshot.CreateSnapshotCmd] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) VOLSS: createSnapshotCmd starts:1382106778549
2013-10-18 17:32:58,925 DEBUG [agent.transport.Request] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Seq 1-111542657: Sending { Cmd , MgmtId: 161342718518, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"560a9f6e-9864-43cc-8096-ed9cd6c97311","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4a975c8c-997a-4d1d-aa88-810fd281cb04","id":1,"poolType":"CLVM","host":"localhost","path":"/vg_primary","port":0}},"name":"ROOT-5","size":8589934592,"path":"4f3e8cfc-d3be-4e55-bc13-5c236a689c83","volumeId":5,"vmName":"i-2-5-VM","accountId":2,"format":"RAW","id":5,"hypervisorType":"KVM"},"parentSnapshotPath":"/dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83/7e85ab28-4ea5-4b5e-8ec1-1abadf2d571e","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4a975c8c-997a-4d1d-aa88-810fd281cb04","id":1,"poolType":"CLVM","host":"localhost","path":"/vg_primary","port":0}},"vmName":"i-2-5-VM","name":"test-100_ROOT-5_20131018143258","hypervisorType":"KVM","id":10}},"wait":0}}] }
2013-10-18 17:32:59,986 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-111542657: Processing: { Ans: , MgmtId: 161342718518, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83/c6c900d1-1377-4347-ba69-9ba09f264f69","id":0}},"result":true,"wait":0}}] }
2013-10-18 17:32:59,986 DEBUG [agent.transport.Request] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Seq 1-111542657: Received: { Ans: , MgmtId: 161342718518, via: 1, Ver: v1, Flags: 10,
}
2013-10-18 17:33:00,497 DEBUG [storage.motion.AncientDataMotionStrategy] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type SNAPSHOT
2013-10-18 17:33:00,547 DEBUG [agent.transport.Request] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Seq 4-1918238786: Sending { Cmd , MgmtId: 161342718518, via: 4, Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83/c6c900d1-1377-4347-ba69-9ba09f264f69","volume":{"uuid":"560a9f6e-9864-43cc-8096-ed9cd6c97311","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4a975c8c-997a-4d1d-aa88-810fd281cb04","id":1,"poolType":"CLVM","host":"localhost","path":"/vg_primary","port":0}},"name":"ROOT-5","size":8589934592,"path":"4f3e8cfc-d3be-4e55-bc13-5c236a689c83","volumeId":5,"vmName":"i-2-5-VM","accountId":2,"format":"RAW","id":5,"hypervisorType":"KVM"},"parentSnapshotPath":"/dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83/7e85ab28-4ea5-4b5e-8ec1-1abadf2d571e","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4a975c8c-997a-4d1d-aa88-810fd281cb04","id":1,"poolType":"CLVM","host":"localhost","path":"/vg_primary","port":0}},"vmName":"i-2-5-VM","name":"test-100_ROOT-5_20131018143258","hypervisorType":"KVM","id":10}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/5","volume":{"uuid":"560a9f6e-9864-43cc-8096-ed9cd6c97311","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"4a975c8c-997a-4d1d-aa88-810fd281cb04","id":1,"poolType":"CLVM","host":"localhost","path":"/vg_primary","port":0}},"name":"ROOT-5","size":8589934592,"path":"4f3e8cfc-d3be-4e55-bc13-5c236a689c83","volumeId":5,"vmName":"i-2-5-VM","accountId":2,"format":"RAW","id":5,"hypervisorType":"KVM"},"parentSnapshotPath":"snapshots/2/5/7e85ab28-4ea5-4b5e-8ec1-1abadf2d571e","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.10.31/export/secondary","_role":"Image"}},"vmName":"i-2-5-VM","name":"test-100_ROOT-5_20131018143258","hypervisorType":"KVM","id":10}},"executeInSequence":true,"wait":21600}}] }
2013-10-18 17:33:01,069 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 4-1918238786: Processing: { Ans: , MgmtId: 161342718518, via: 4, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Disk /dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83 has no snapshot called 5ece5182b7f6f10ef1b66b558f3d0bbb.","wait":0}}] }
2013-10-18 17:33:01,070 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-8:null) Seq 4-1918238786: No more commands found
2013-10-18 17:33:01,070 DEBUG [agent.transport.Request] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Seq 4-1918238786: Received: { Ans: , MgmtId: 161342718518, via: 4, Ver: v1, Flags: 110,
}
2013-10-18 17:33:01,336 DEBUG [storage.snapshot.SnapshotManagerImpl] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Failed to create snapshot
com.cloud.utils.exception.CloudRuntimeException: Disk /dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83 has no snapshot called 5ece5182b7f6f10ef1b66b558f3d0bbb.
at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:280)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:138)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:264)
at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1013)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1307)
at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2720)
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:679)
2013-10-18 17:33:01,427 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Take snapshot: 5 failed
com.cloud.utils.exception.CloudRuntimeException: Failed to create snapshot
at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1040)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1307)
at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2720)
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:679)
Caused by: com.cloud.utils.exception.CloudRuntimeException: Disk /dev/vg_primary/4f3e8cfc-d3be-4e55-bc13-5c236a689c83 has no snapshot called 5ece5182b7f6f10ef1b66b558f3d0bbb.
at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:280)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:138)
at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:264)
at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1013)
... 16 more
2013-10-18 17:33:01,509 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-22:job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ]) Complete async job-41 = [ 88ec27d7-78af-4664-a01b-eeca4469e37c ], jobStatus: 2, resultCode: 530, result: Error Code: 530 Error text: Failed to create snapshot due to an internal error creating snapshot for volume 5