[
https://issues.apache.org/jira/browse/CLOUDSTACK-4324?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sanjeev N updated CLOUDSTACK-4324:
----------------------------------
Attachment: cloud.dmp
management-server.rar
Attached management server log file and cloud DB
> [Object_Store_Refactor] DB Exception while expunging the snapshot which was
> in Error state
> ------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4324
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4324
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Snapshot, Storage Controller
> Affects Versions: 4.2.0
> Environment: Latest build from ACS 4.2 branch
> Storage: S3 for secondary, NFS for staging and Local for primary storage
> Cluster: KVM
> Reporter: Sanjeev N
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: cloud.dmp, management-server.rar
>
>
> DB Exception while expunging the snapshot which was in Error state
> Steps to Reproduce:
> ================
> 1. Bring up CS with kvm cluster using S3 for secondary, NFS for staging and
> Local for primary storage
> 2.Deploy guest vm with root and data disk
> 3.Configure recurring snapshot policy on root and data disk (eg:configure
> hourly on both to start almost at the same time)
> Result:
> ======
> On one of the disks snapshot creation failed (Not sure of this behaviour, so
> I have sent a mail to dev mailing list to confirm the expected behavior on
> kvm)
> StorageManager-Scavenger-1 tried to expunge the snapshot which was in error
> state due to above failure, however DBException observed during Transaction
> rollback.
> Following is the log snippet :
> ======================
> 2013-08-14 05:51:43,900 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
> (SnapshotPollTask:null) Scheduling 1 snapshot for volume 12 for schedule id:
> 1 at 2013-08-14 09:50:00 GMT
> 2013-08-14 05:51:43,975 DEBUG [cloud.async.AsyncJobManagerImpl]
> (SnapshotPollTask:null) submit async job-27 = [
> 1254eeae-f809-41bf-880f-289fe6127fcf ], details: AsyncJobVO {id:27, userId:
> 1, accountId: 2, sessionKey: null, instanceType: Snapshot, instanceId: 3,
> cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd,
> cmdOriginator: null, cmdInfo:
> {"id":"3","ctxUserId":"1","volumeid":"12","ctxAccountId":"2","ctxStartEventId":"1","policyid":"1"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 6615759585382,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-14 05:51:43,986 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Executing
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-27
> = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]
> 2013-08-14 05:51:44,031 DEBUG [storage.snapshot.SnapshotSchedulerImpl]
> (SnapshotPollTask:null) Scheduling 1 snapshot for volume 13 for schedule id:
> 2 at 2013-08-14 09:51:00 GMT
> 2013-08-14 05:51:44,057 INFO [user.snapshot.CreateSnapshotCmd]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) VOLSS:
> createSnapshotCmd starts:1376473904057
> 2013-08-14 05:51:44,114 DEBUG [cloud.async.AsyncJobManagerImpl]
> (SnapshotPollTask:null) submit async job-28 = [
> ca95499a-3323-4fee-bb12-69a4df9285f3 ], details: AsyncJobVO {id:28, userId:
> 1, accountId: 2, sessionKey: null, instanceType: Snapshot, instanceId: 4,
> cmd: org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd,
> cmdOriginator: null, cmdInfo:
> {"id":"4","ctxUserId":"1","volumeid":"13","ctxAccountId":"2","ctxStartEventId":"1","policyid":"2"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 6615759585382,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-08-14 05:51:44,116 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-18:job-28 = [ ca95499a-3323-4fee-bb12-69a4df9285f3 ]) Executing
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for job-28
> = [ ca95499a-3323-4fee-bb12-69a4df9285f3 ]
> 2013-08-14 05:51:44,144 DEBUG [agent.transport.Request]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Seq
> 1-1253835473: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags:
> 100011,
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"47359dc7-5a36-4ab9-bc70-d4e6e694fe8b","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a01b8b56-4987-4843-be07-e48f1c584498","id":1,"poolType":"Filesystem","host":"10.147.40.14","path":"/var/lib/libvirt/images","port":0}},"name":"ROOT-8","size":472312242,"path":"d742d9f4-b1a8-49a5-8161-892c4ef381ad","volumeId":12,"vmName":"i-2-8-VM","accountId":2,"format":"QCOW2","id":12,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a01b8b56-4987-4843-be07-e48f1c584498","id":1,"poolType":"Filesystem","host":"10.147.40.14","path":"/var/lib/libvirt/images","port":0}},"vmName":"i-2-8-VM","name":"HourlyDaily_ROOT-8_20130814095143","hypervisorType":"KVM","id":3}},"wait":0}}]
> }
> 2013-08-14 05:51:44,156 INFO [user.snapshot.CreateSnapshotCmd]
> (Job-Executor-18:job-28 = [ ca95499a-3323-4fee-bb12-69a4df9285f3 ]) VOLSS:
> createSnapshotCmd starts:1376473904156
> 2013-08-14 05:51:44,201 DEBUG [agent.transport.Request]
> (Job-Executor-18:job-28 = [ ca95499a-3323-4fee-bb12-69a4df9285f3 ]) Seq
> 1-1253835474: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags:
> 100011,
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"0023a635-b1ca-499d-91b3-ddca2a4fa84d","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a01b8b56-4987-4843-be07-e48f1c584498","id":1,"poolType":"Filesystem","host":"10.147.40.14","path":"/var/lib/libvirt/images","port":0}},"name":"DATA-8","size":5368709120,"path":"8a8b01a1-898a-498f-9b13-ca8b873586c5","volumeId":13,"vmName":"i-2-8-VM","accountId":2,"format":"QCOW2","id":13,"hypervisorType":"KVM"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a01b8b56-4987-4843-be07-e48f1c584498","id":1,"poolType":"Filesystem","host":"10.147.40.14","path":"/var/lib/libvirt/images","port":0}},"vmName":"i-2-8-VM","name":"HourlyDaily_DATA-8_20130814095144","hypervisorType":"KVM","id":4}},"wait":0}}]
> }
> 2013-08-14 05:52:19,966 DEBUG [agent.transport.Request]
> (AgentManager-Handler-2:null) Seq 1-1253835473: Processing: { Ans: , MgmtId:
> 6615759585382, via: 1, Ver: v1, Flags: 10,
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"result":false,"details":"Failed
> to manage snapshot: org.libvirt.LibvirtException: Timed out during
> operation: cannot acquire state change lock","wait":0}}] }
> 2013-08-14 05:52:19,966 DEBUG [agent.transport.Request]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Seq
> 1-1253835473: Received: { Ans: , MgmtId: 6615759585382, via: 1, Ver: v1,
> Flags: 10, { CreateObjectAnswer } }
> 2013-08-14 05:52:19,966 DEBUG [storage.snapshot.SnapshotServiceImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) create
> snapshot HourlyDaily_ROOT-8_20130814095143 failed: Failed to manage snapshot:
> org.libvirt.LibvirtException: Timed out during operation: cannot acquire
> state change lock
> 2013-08-14 05:52:20,084 WARN
> [storage.datastore.ObjectInDataStoreManagerImpl] (Job-Executor-17:job-27 = [
> 1254eeae-f809-41bf-880f-289fe6127fcf ]) Unsupported data object (SNAPSHOT,
> org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@377a6189), no
> need to delete from object in store ref table
> 2013-08-14 05:52:20,085 DEBUG [storage.snapshot.SnapshotServiceImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Failed to
> create snapshot:Failed to manage snapshot: org.libvirt.LibvirtException:
> Timed out during operation: cannot acquire state change lock
> 2013-08-14 05:52:20,085 DEBUG [storage.snapshot.SnapshotManagerImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Failed to
> create snapshotcom.cloud.utils.exception.CloudRuntimeException: Failed to
> manage snapshot: org.libvirt.LibvirtException: Timed out during operation:
> cannot acquire state change lock
> at
> org.apache.cloudstack.storage.snapshot.SnapshotServiceImpl.takeSnapshot(SnapshotServiceImpl.java:215)
> at
> org.apache.cloudstack.storage.snapshot.XenserverSnapshotStrategy.takeSnapshot(XenserverSnapshotStrategy.java:248)
> at
> com.cloud.storage.snapshot.SnapshotManagerImpl.takeSnapshot(SnapshotManagerImpl.java:1004)
> at
> org.apache.cloudstack.storage.volume.VolumeServiceImpl.takeSnapshot(VolumeServiceImpl.java:1256)
> at
> com.cloud.storage.VolumeManagerImpl.takeSnapshot(VolumeManagerImpl.java:2703)
> 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-08-14 05:52:20,091 DEBUG [storage.volume.VolumeServiceImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Take
> snapshot: 12 failed: com.cloud.utils.exception.CloudRuntimeException: Failed
> to create snapshot
> 2013-08-14 05:52:20,097 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-17:job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ]) Complete
> async job-27 = [ 1254eeae-f809-41bf-880f-289fe6127fcf ], jobStatus: 2,
> resultCode: 530, result: Error Code: 530 Error text: Failed to create
> snapshot due to an internal error creating snapshot for volume 12
> 2013-08-14 05:53:33,389 DEBUG [db.Transaction.Transaction]
> (StorageManager-Scavenger-1:null) Rolling back the transaction: Time = 1 Name
> = expunge; called by
> -Transaction.rollback:898-Transaction.removeUpTo:841-Transaction.close:665-TransactionContextBuilder.interceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:133-StorageManagerImpl.cleanupStorage:1092-StorageManagerImpl$StorageGarbageCollector.run:1364-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRunAndReset:351-FutureTask.runAndReset:178-ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201:165-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:267
> 2013-08-14 05:53:33,392 WARN [cloud.storage.StorageManagerImpl]
> (StorageManager-Scavenger-1:null) Unable to destroy 3
> com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
> com.mysql.jdbc.JDBC4PreparedStatement@4582c61b: DELETE FROM snapshots WHERE
> snapshots.id= 3
> at com.cloud.utils.db.GenericDaoBase.expunge(GenericDaoBase.java:1143)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
> at
> com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1092)
> at
> com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.run(StorageManagerImpl.java:1364)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> 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)
> Caused by:
> com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException:
> Cannot delete or update a parent row: a foreign key constraint fails
> (`cloud`.`snapshot_store_ref`, CONSTRAINT
> `fk_snapshot_store_ref__snapshot_id` FOREIGN KEY (`snapshot_id`) REFERENCES
> `snapshots` (`id`))
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
> Method)
> at
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
> at
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
> at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
> at com.mysql.jdbc.Util.getInstance(Util.java:386)
> at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1040)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
> at
> com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
> at
> com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2450)
> at
> com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2371)
> at
> com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2355)
> at
> org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
> at
> org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
> at com.cloud.utils.db.GenericDaoBase.expunge(GenericDaoBase.java:1134)
> ... 15 more
--
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
