cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Sanjeev N (JIRA)" <j...@apache.org>
Subject [jira] [Closed] (CLOUDSTACK-4324) [Object_Store_Refactor] DB Exception while expunging the snapshot which was in Error state
Date Wed, 28 Aug 2013 09:42:52 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-4324?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Sanjeev N closed CLOUDSTACK-4324.
---------------------------------


Verified with latest build. Not seeing the issue any more.
                
> [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
>            Assignee: edison su
>            Priority: Critical
>             Fix For: 4.2.0
>
>         Attachments: cloud.dmp, cloud.dmp, management-server.rar, 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( .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

Mime
View raw message