angeline shen created CLOUDSTACK-3790: -----------------------------------------
Summary: KVM - Fail to create recurring snapshot : pool is already active Key: CLOUDSTACK-3790 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3790 Project: CloudStack Issue Type: Bug Security Level: Public (Anyone can view this level - this is the default.) Components: Management Server Affects Versions: 4.2.0 Environment: MS build CloudPlatform-4.2-246-rhel6.3.tar.gz host KVM build CloudPlatform-4.2-246-rhel6.3.tar.gz Reporter: angeline shen Assignee: edison su Priority: Critical Fix For: 4.2.0 1. advance zone. domain: d1 domain admin: d1domain domain: d2 user : d2user 2. login : admin . create VPC network & VMs with DATA disk login: d1domain. create VPC network & VMs with DATA disk login: d2user. create VPC network & VMs with DATA disk 3. login as each of above users. setup hourly recurring snapshots for all ROOT and DATA disks to same recurring schedule, for example , all at 9 minutes pass the hour. Result: there are some snapshots generated with status CreateOnPrimary , Failed to create snapshot due to pool is already active : 2013-07-23 22:04:49,920 DEBUG [agent.transport.Request] (Job-Executor-42:job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ]) Seq 1-1490617925: Sending { Cmd , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 100011, [{"or g.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/79884886-a3ee-31a7-856c-805e18c48f88/b52e5c2b-fc3e-4292-bda5-cb961efb94c7/c733fc4e-4d16-481f-9 e20-2ed2519d6b3d","volume":{"uuid":"a39f007b-b014-4e6c-a3fa-8bce7a9ba213","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poo lType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/angie/primary/kvm63","port":2049}},"name":"ROOT-13","size":147456,"path":"b52e5c2b-fc3e-4292-bda5-cb961efb94c7","volumeId":15,"vmName":"i-4-13-VM", "accountId":4,"format":"QCOW2","id":15},"parentSnapshotPath":"/mnt/79884886-a3ee-31a7-856c-805e18c48f88/b52e5c2b-fc3e-4292-bda5-cb961efb94c7/29669eb5-1525-4745-81c4-6ca6ad239af0","dataStore":{"org.apache.cloudstack.stor age.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/angie/primary/kvm63","port":2049}},"vmName":"i-4-13-VM","name" :"z1vpc3G3d2userV32_ROOT-13_20130724050449","hypervisorType":"None","id":28}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/4/15","volume":{"uuid":"a39f007b-b014-4e6c-a3fa-8bce7a9ba213 ","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/ angie/primary/kvm63","port":2049}},"name":"ROOT-13","size":147456,"path":"b52e5c2b-fc3e-4292-bda5-cb961efb94c7","volumeId":15,"vmName":"i-4-13-VM","accountId":4,"format":"QCOW2","id":15},"parentSnapshotPath":"snapshots/ 4/15/29669eb5-1525-4745-81c4-6ca6ad239af0","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232/export/home/angie/secondary/kvm63","_role":"Image"}},"vmName":"i-4-13-VM","name":"z1vpc3G3d2userV32_RO OT-13_20130724050449","hypervisorType":"None","id":28}},"executeInSequence":false,"wait":21600}}] } 2013-07-23 22:04:50,085 DEBUG [agent.transport.Request] (AgentManager-Handler-6:null) Seq 1-1490617925: Processing: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.C opyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Requested operation is not valid: pool is already active as '83602b3b-9b52-3016-871d-10883d294c18'" ,"wait":0}}] } 2013-07-23 22:04:50,085 DEBUG [agent.transport.Request] (Job-Executor-42:job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ]) Seq 1-1490617925: Received: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, { Copy CmdAnswer } } 2013-07-23 22:04:50,097 DEBUG [storage.snapshot.SnapshotManagerImpl] (Job-Executor-42:job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ]) Failed to create snapshot com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Requested operation is not valid: pool is already active as '83602b3b-9b52-3016-871d-10883d 294c18' at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:286) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:127) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:217) at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:992) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1185) at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2654) 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:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-07-23 22:04:50,106 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-42:job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ]) Take snapshot: 15 failed: com.cloud.utils.exception.CloudRuntimeException: Failed to c reate snapshot 2013-07-23 22:04:50,114 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-42:job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ]) Complete async job-56 = [ 3def22de-176e-45a7-b72b-98aaef57b906 ], jobStatus: 2, resultC ode: 530, result: Error Code: 530 Error text: Failed to create snapshot due to an internal error creating snapshot for volume 15 2013-07-23 22:04:51,383 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) StorageCollector is running... .................. 2013-07-23 20:04:49,902 DEBUG [agent.transport.Request] (Job-Executor-29:job-43 = [ 2362369a-a0ed-4554-852c-844b0e078670 ]) Seq 1-1490617352: Sending { Cmd , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 100011, [{"or g.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"/mnt/79884886-a3ee-31a7-856c-805e18c48f88/925e81ef-205a-4fd4-b3cf-923b709a2e3b/44e288de-1158-4343-b 660-703b53208d2a","volume":{"uuid":"6c1d767f-c297-4bf2-8108-c0fa4d8c4862","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poo lType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/angie/primary/kvm63","port":2049}},"name":"ROOT-12","size":147456,"path":"925e81ef-205a-4fd4-b3cf-923b709a2e3b","volumeId":14,"vmName":"i-4-12-VM", "accountId":4,"format":"QCOW2","id":14},"parentSnapshotPath":"/mnt/79884886-a3ee-31a7-856c-805e18c48f88/925e81ef-205a-4fd4-b3cf-923b709a2e3b/3a91bcf2-9121-46b7-a720-c53daf617269","dataStore":{"org.apache.cloudstack.stor age.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/angie/primary/kvm63","port":2049}},"vmName":"i-4-12-VM","name" :"z1vpc3d2userV31_ROOT-12_20130724030449","hypervisorType":"None","id":15}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/4/14","volume":{"uuid":"6c1d767f-c297-4bf2-8108-c0fa4d8c4862", "volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"79884886-a3ee-31a7-856c-805e18c48f88","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/an gie/primary/kvm63","port":2049}},"name":"ROOT-12","size":147456,"path":"925e81ef-205a-4fd4-b3cf-923b709a2e3b","volumeId":14,"vmName":"i-4-12-VM","accountId":4,"format":"QCOW2","id":14},"parentSnapshotPath":"snapshots/4/ 14/3a91bcf2-9121-46b7-a720-c53daf617269","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232/export/home/angie/secondary/kvm63","_role":"Image"}},"vmName":"i-4-12-VM","name":"z1vpc3d2userV31_ROOT-1 2_20130724030449","hypervisorType":"None","id":15}},"executeInSequence":false,"wait":21600}}] } 2013-07-23 20:04:50,023 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) HostStatsCollector is running... 2013-07-23 20:04:50,029 DEBUG [agent.manager.AgentAttache] (StatsCollector-3:null) Request seq: 1490617353 2013-07-23 20:04:50,029 DEBUG [agent.manager.AgentAttache] (StatsCollector-3:null) waiting to send 1490617353 2013-07-23 20:04:50,029 DEBUG [agent.manager.AgentAttache] (StatsCollector-3:null) entering synchronize block for sending 1490617353 2013-07-23 20:04:50,030 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 1-1490617350: Processing: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.NetworkUsageAnswer ":{"routerName":"r-11-VM","bytesSent":156008,"bytesReceived":7127289,"result":true,"details":"","wait":0}}] } 2013-07-23 20:04:50,030 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-1490617350: Received: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } 2013-07-23 20:04:50,030 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: 2013-07-23 20:04:50,127 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 1-1490617352: Processing: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.C opyCmdAnswer":{"result":false,"details":"com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Requested operation is not valid: pool is already active as '83602b3b-9b52-3016-871d-10883d294c18'" ,"wait":0}}] } 2013-07-23 20:04:50,127 DEBUG [agent.transport.Request] (Job-Executor-29:job-43 = [ 2362369a-a0ed-4554-852c-844b0e078670 ]) Seq 1-1490617352: Received: { Ans: , MgmtId: 6655051826959, via: 1, Ver: v1, Flags: 10, { Copy CmdAnswer } } 2013-07-23 20:04:50,139 DEBUG [storage.snapshot.SnapshotManagerImpl] (Job-Executor-29:job-43 = [ 2362369a-a0ed-4554-852c-844b0e078670 ]) Failed to create snapshot com.cloud.utils.exception.CloudRuntimeException: com.cloud.utils.exception.CloudRuntimeException: org.libvirt.LibvirtException: Requested operation is not valid: pool is already active as '83602b3b-9b52-3016-871d-10883d 294c18' at org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.backupSnapshot(SnapshotServiceImpl.java:286) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.backupSnapshot(XenserverSnapshotStrategy.java:127) at org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:217) at com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:992) at org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1185) at com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2654) 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:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:679) 2013-07-23 20:04:50,146 DEBUG [storage.volume.VolumeServiceImpl] (Job-Executor-29:job-43 = [ 2362369a-a0ed-4554-852c-844b0e078670 ]) Take snapshot: 14 failed: com.cloud.utils.exception.CloudRuntimeException: Failed to c reate snapshot 2013-07-23 20:04:50,153 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-29:job-43 = [ 2362 -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira