Sanjeev N created CLOUDSTACK-3416:
-------------------------------------
Summary: [Object_Store_Refactor] Extract Volume multiple times on
the same volume results in failure
Key: CLOUDSTACK-3416
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3416
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: latest build from master branch
Reporter: Sanjeev N
Fix For: 4.2.0
[Object_Store_Refactor] Extract Volume multiple times on the same volume
results in failure
Steps to Reproduce:
================
1.Bring up CS in advanced zone with s3 as the storage provider
2.create a guest vm using the default cent OS template
3.Create a small disk, attach to a vm and detach it
4.Extract volume
This is copy the volume from primary to secondary cache storage and then to s3
and will provide presinged URL to download the volume.
5.Repeat step 4 couple of times
Extract volume fails with following exceptions:
2013-07-09 11:27:46,950 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
===START=== 10.146.0.20 -- GET
command=extractVolume&id=9972a317-8f8f-49d3-b91a-7eac8c193b20&zoneid=2c82a035-11cf-4303-9724-e35129dbb07e&mode=HTTP_DOWNLOAD&response=json&sessionkey=kRXjQ8Ib6WEGFB8nHLPghtXoVxs%3D&_=1373363953955
2013-07-09 11:27:46,991 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-25:null) submit async job-17, details: AsyncJobVO {id:17,
userId: 2, accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 6,
cmd: org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd,
cmdOriginator: null, cmdInfo:
{"response":"json","id":"9972a317-8f8f-49d3-b91a-7eac8c193b20","sessionkey":"kRXjQ8Ib6WEGFB8nHLPghtXoVxs\u003d","cmdEventType":"VOLUME.EXTRACT","ctxUserId":"2","zoneid":"2c82a035-11cf-4303-9724-e35129dbb07e","httpmethod":"GET","_":"1373363953955","ctxAccountId":"2","ctxStartEventId":"68","mode":"HTTP_DOWNLOAD"},
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-07-09 11:27:46,995 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
===END=== 10.146.0.20 -- GET
command=extractVolume&id=9972a317-8f8f-49d3-b91a-7eac8c193b20&zoneid=2c82a035-11cf-4303-9724-e35129dbb07e&mode=HTTP_DOWNLOAD&response=json&sessionkey=kRXjQ8Ib6WEGFB8nHLPghtXoVxs%3D&_=1373363953955
2013-07-09 11:27:46,998 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-17:job-17) Executing
org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd for job-17
2013-07-09 11:27:47,066 DEBUG [storage.volume.VolumeObject]
(Job-Executor-17:job-17) Failed to update state
com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new state
from Creating via CreateOnlyRequested
at com.cloud.utils.fsm.StateMachine2.getNextState(StateMachine2.java:83)
at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:100)
at
org.apache.cloudstack.storage.datastore.ObjectInDataStoreManagerImpl.update(ObjectInDataStoreManagerImpl.java:242)
at
org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:306)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromPrimaryToImage(VolumeServiceImpl.java:659)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:715)
at
com.cloud.storage.VolumeManagerImpl.extractVolume(VolumeManagerImpl.java:2776)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd.execute(ExtractVolumeCmd.java:130)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:514)
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-09 11:27:47,074 ERROR [storage.volume.VolumeServiceImpl]
(Job-Executor-17:job-17) failed to copy volume to image store
com.cloud.utils.exception.CloudRuntimeException: Failed to update
state:com.cloud.utils.fsm.NoTransitionException: Unable to transition to a new
state from Creating via CreateOnlyRequested
at
org.apache.cloudstack.storage.volume.VolumeObject.processEventOnly(VolumeObject.java:309)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolumeFromPrimaryToImage(VolumeServiceImpl.java:659)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.copyVolume(VolumeServiceImpl.java:715)
at
com.cloud.storage.VolumeManagerImpl.extractVolume(VolumeManagerImpl.java:2776)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd.execute(ExtractVolumeCmd.java:130)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:514)
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-09 11:27:47,094 DEBUG [agent.transport.Request]
(Job-Executor-17:job-17) Seq 3-847708178: Sending { Cmd , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9972a317-8f8f-49d3-b91a-7eac8c193b20","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.S3TO":{"id":2,"uuid":"0e7a46b0-c9fd-4d7f-9f68-3e346a2bcd35","accessKey":"9M7I6JPYZHDNLG43TWCD","secretKey":"KL7IAVYcYO8URicgniNjeCmL7k3tYKMpJRXNHw==","endPoint":"10.147.29.57:8080","bucketName":"imagestore","httpsFlag":false,"created":"Jul
9, 2013 7:59:12
AM","enableRRS":false}},"name":"test","size":5368709120,"path":"volumes/2/6/727c5651-56b4-466c-993b-9384c29b9c41.vhd","volumeId":6,"accountId":2,"format":"VHD","id":6}},"wait":0}}]
}
2013-07-09 11:27:47,201 DEBUG [agent.transport.Request]
(AgentManager-Handler-1:null) Seq 3-847708178: Processing: { Ans: , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"Deleted volume %s from
bucket imagestore.","wait":0}}] }
2013-07-09 11:27:47,202 DEBUG [agent.transport.Request]
(Job-Executor-17:job-17) Seq 3-847708178: Received: { Ans: , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 10, { Answer } }
2013-07-09 11:27:47,261 WARN [storage.datastore.ObjectInDataStoreManagerImpl]
(Job-Executor-17:job-17) Unsupported data object (VOLUME,
org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@6f941e86)
2013-07-09 11:27:47,271 ERROR [cloud.async.AsyncJobManagerImpl]
(Job-Executor-17:job-17) Unexpected exception while executing
org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to copy the volume from
the source primary storage pool to secondary storage.
at
com.cloud.storage.VolumeManagerImpl.extractVolume(VolumeManagerImpl.java:2790)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.volume.ExtractVolumeCmd.execute(ExtractVolumeCmd.java:130)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:514)
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-09 11:27:47,272 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-17:job-17) Complete async job-17, jobStatus: 2, resultCode: 530,
result: Error Code: 530 Error text: Failed to copy the volume from the source
primary storage pool to secondary storage.
Since there was a failure in extractVolumecmd, it executed DeleteCommand and
deleted the volume which got copied to S3 after step4:
2013-07-09 11:27:47,094 DEBUG [agent.transport.Request]
(Job-Executor-17:job-17) Seq 3-847708178: Sending { Cmd , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9972a317-8f8f-49d3-b91a-7eac8c193b20","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.S3TO":{"id":2,"uuid":"0e7a46b0-c9fd-4d7f-9f68-3e346a2bcd35","accessKey":"9M7I6JPYZHDNLG43TWCD","secretKey":"KL7IAVYcYO8URicgniNjeCmL7k3tYKMpJRXNHw==","endPoint":"10.147.29.57:8080","bucketName":"imagestore","httpsFlag":false,"created":"Jul
9, 2013 7:59:12
AM","enableRRS":false}},"name":"test","size":5368709120,"path":"volumes/2/6/727c5651-56b4-466c-993b-9384c29b9c41.vhd","volumeId":6,"accountId":2,"format":"VHD","id":6}},"wait":0}}]
}
2013-07-09 11:27:47,201 DEBUG [agent.transport.Request]
(AgentManager-Handler-1:null) Seq 3-847708178: Processing: { Ans: , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"details":"Deleted volume %s from
bucket imagestore.","wait":0}}] }
At this stage volume was deleted only from s3 but not from NFS cache storage.
Following are the cloud DB entries:
mysql> select * from volumes where id=6;
+----+------------+-----------+---------+--------------+-------------+-----------+------+--------------------------------------+------------+--------+--------------------------------------+--------+----------------+------------+---------+-------------+-----------+------------------+-------------+----------------------------+-------------+---------------------+----------+---------------------+---------+-------+------------+--------------+-----------+----------------+--------+----------+----------+
| id | account_id | domain_id | pool_id | last_pool_id | instance_id |
device_id | name | uuid | size | folder |
path | pod_id | data_center_id | iscsi_name |
host_ip | volume_type | pool_type | disk_offering_id | template_id |
first_snapshot_backup_uuid | recreatable | created | attached |
updated | removed | state | chain_info | update_count | disk_type |
display_volume | format | min_iops | max_iops |
+----+------------+-----------+---------+--------------+-------------+-----------+------+--------------------------------------+------------+--------+--------------------------------------+--------+----------------+------------+---------+-------------+-----------+------------------+-------------+----------------------------+-------------+---------------------+----------+---------------------+---------+-------+------------+--------------+-----------+----------------+--------+----------+----------+
| 6 | 2 | 1 | 1 | NULL | NULL |
NULL | test | 9972a317-8f8f-49d3-b91a-7eac8c193b20 | 5368709120 | NULL |
30608de5-9cdb-48c8-a321-509f9b993afb | NULL | 1 | NULL |
NULL | DATADISK | NULL | 3 | NULL | NULL
| 0 | 2013-07-09 15:13:22 | NULL | 2013-07-09
15:27:47 | NULL | Ready | NULL | 10 | NULL |
1 | VHD | NULL | NULL |
+----+------------+-----------+---------+--------------+-------------+-----------+------+--------------------------------------+------------+--------+--------------------------------------+--------+----------------+------------+---------+-------------+-----------+------------------+-------------+----------------------------+-------------+---------------------+----------+---------------------+---------+-------+------------+--------------+-----------+----------------+--------+----------+----------+
1 row in set (0.01 sec)
mysql> select * from volume_store_ref;
+----+----------+-----------+---------+---------------------+---------------------+--------+--------------+------------+---------------+----------------+----------+-----------+------------+------------------------------------------------------+------+-----------+-----------+--------------+---------+---------------------+
| id | store_id | volume_id | zone_id | created | last_updated
| job_id | download_pct | size | physical_size | download_state |
checksum | error_str | local_path | install_path
| url | state | destroyed | update_count | ref_cnt | updated
|
+----+----------+-----------+---------+---------------------+---------------------+--------+--------------+------------+---------------+----------------+----------+-----------+------------+------------------------------------------------------+------+-----------+-----------+--------------+---------+---------------------+
| 2 | 1 | 6 | 0 | 2013-07-09 15:19:57 | 2013-07-09
15:25:03 | NULL | 0 | 5368709120 | 0 | NULL
| NULL | NULL | NULL |
volumes/2/6/727c5651-56b4-466c-993b-9384c29b9c41.vhd | NULL | Ready |
0 | 2 | 0 | 2013-07-09 15:20:16 |
| 3 | 2 | 6 | 0 | 2013-07-09 15:25:02 | NULL
| NULL | 0 | 2114048 | 0 | NULL | NULL
| NULL | NULL |
volumes/2/6/727c5651-56b4-466c-993b-9384c29b9c41.vhd | NULL | Creating |
0 | 1 | 0 | 2013-07-09 15:25:03 |
| 5 | 2 | 6 | 0 | 2013-07-09 15:27:47 | NULL
| NULL | 0 | 0 | 0 | NULL | NULL
| NULL | NULL | volumes/2/6
| NULL | Allocated | 0 | 0 | 0 | NULL
|
+----+----------+-----------+---------+---------------------+---------------------+--------+--------------+------------+---------------+----------------+----------+-----------+------------+------------------------------------------------------+------+-----------+-----------+--------------+---------+---------------------+
3 rows in set (0.00 sec)
--
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
