Sanjeev N created CLOUDSTACK-4112:
-------------------------------------
Summary: [Object_store_refactor] Attaching uploaded volume fails
with DB Exception on: com.mysql.jdbc.JDBC4PreparedStatement@53b69b6d:
Key: CLOUDSTACK-4112
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4112
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Storage Controller, VMware, Volumes
Affects Versions: 4.2.0
Environment: Latest build from ACS 4.2 branch.
Storage: S3 for Secondary, NFS for secondarystaging, ISCSI for Primary
Cluster: VMWare
Reporter: Sanjeev N
Priority: Critical
Fix For: 4.2.0
Attachments: cloud.dmp, management-server.rar
[Object_store_refactor] Attaching uploaded volume fails with DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@53b69b6d: UPDATE volumes SET
volumes.path=_binary'd093eb32a65a49e08e8237edac6772c9', volumes.pool_id=1,
volumes.size=null WHERE volumes.id = 12
Steps to Reproduce:
=================
1.Bring up CS with VMWare cluster using S3 for Secondary, NFS for secondary
staging and ISCSI for Primary storage.
2.Deploy guest vm using default cent os template
3.Upload volume using API:
http://10.147.59.126:8096/client/api?command=uploadVolume&format=OVA&name=cent53-upload&url=http://10.147.28.7/templates/vmware/CentOS5.3-x86_64.ova&zoneid=a7c59acd-1b2f-4f06-b50b-bd79e113c692&account=admin&domainid=1
4.Attach volume to guest vm
Result:
======
Attaching uploaded volume to guest vm is failing with DB Exception.
Observations:
==========
During attach volume process, uploaded volume was successfully copied from S3
to staging secondary storage. copyCmdAnswer result is true even for copying
volume from staging secondary storage to primary storage.
However attaching volume failed with DB Exception.
Log snippet is as follows:
2013-08-06 08:06:48,905 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-13:null) submit async job-27 = [
1a25a5ce-76b8-4dd4-be82-2723a91daff6 ], details: AsyncJobVO {id:27, userId: 2,
accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 12, cmd:
org.apache.cloudstack.api.command.user.volume.AttachVolumeCmd, cmdOriginator:
null, cmdInfo:
{"id":"3b18f8e5-e7e9-4658-9a85-a58275d1fbef","response":"json","sessionkey":"foQa9K4dPmYo8uEiAcolaTVR6yI\u003d","cmdEventType":"VOLUME.ATTACH","ctxUserId":"2","virtualMachineId":"e22af295-6429-4338-8a68-b6dba7753931","httpmethod":"GET","_":"1375790796785","ctxAccountId":"2","ctxStartEventId":"102"},
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-06 08:06:48,908 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
===END=== 10.146.0.20 -- GET
command=attachVolume&id=3b18f8e5-e7e9-4658-9a85-a58275d1fbef&virtualMachineId=e22af295-6429-4338-8a68-b6dba7753931&response=json&sessionkey=foQa9K4dPmYo8uEiAcolaTVR6yI%3D&_=1375790796785
2013-08-06 08:06:48,912 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Executing
org.apache.cloudstack.api.command.user.volume.AttachVolumeCmd for job-27 = [
1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]
2013-08-06 08:06:48,967 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-08-06 08:06:48,969 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-28:job-27 =
[ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) ClusterScopeStoragePoolAllocator
looking for storage pool
2013-08-06 08:06:48,970 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-28:job-27 =
[ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Looking for pools in dc: 1 pod:1
cluster:1
2013-08-06 08:06:48,976 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Checking if
storage pool is suitable, name: null ,poolId: 1
2013-08-06 08:06:48,985 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Checking
pool 1 for storage, totalSize: 93952409600, usedBytes: 4970250240, usedPct:
0.052901785714285714, disable threshold: 0.85
2013-08-06 08:06:48,999 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Checking
pool: 1 for volume allocation [Vol[12|vm=null|DATADISK]], maxSize :
93952409600, totalAllocatedSize : 1769931776, askingSize : 459320832, allocated
disable threshold: 0.85
2013-08-06 08:06:48,999 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-28:job-27 =
[ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) FirstFitStoragePoolAllocator
returning 1 suitable storage pools
2013-08-06 08:06:49,033 DEBUG [storage.motion.AncientDataMotionStrategy]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) copyAsync
inspecting src type VOLUME copyAsync inspecting dest type VOLUME
2013-08-06 08:06:49,043 DEBUG [storage.motion.AncientDataMotionStrategy]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ])
needCacheStorage true, dest at null dest role
Primaryvolumes/2/12/CentOS5.3-x86_64.ova src role Image
2013-08-06 08:06:49,068 DEBUG [storage.motion.AncientDataMotionStrategy]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) copyAsync
inspecting src type VOLUME copyAsync inspecting dest type VOLUME
2013-08-06 08:06:49,112 DEBUG [agent.transport.Request] (Job-Executor-28:job-27
= [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Seq 3-1317535777: Sending { Cmd ,
MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3b18f8e5-e7e9-4658-9a85-a58275d1fbef","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.S3TO":{"id":9,"uuid":"fc2025c3-0d27-4f54-a7e0-c39e4494420b","endPoint":"10.147.29.57:8080","bucketName":"imagestore","httpsFlag":false,"created":"Aug
6, 2013 7:50:34
AM","enableRRS":false}},"name":"cent53-upload","size":459320832,"path":"volumes/2/12/CentOS5.3-x86_64.ova","volumeId":12,"accountId":2,"format":"OVA","id":12,"hypervisorType":"None"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3b18f8e5-e7e9-4658-9a85-a58275d1fbef","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_esx_os","_role":"ImageCache"}},"name":"cent53-upload","size":459320832,"path":"volumes/2/12","volumeId":12,"accountId":2,"format":"OVA","id":12,"hypervisorType":"None"}},"executeInSequence":false,"wait":10800}}]
}
2013-08-06 08:07:16,725 DEBUG [agent.transport.Request]
(AgentManager-Handler-8:null) Seq 3-1317535777: Processing: { Ans: , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"name":"24998551-bab1-4b9c-864c-cdcc23b21a3c.ova","size":459320832,"path":"volumes/2/12/24998551-bab1-4b9c-864c-cdcc23b21a3c.ova","accountId":0,"id":0}},"result":true,"wait":0}}]
}
2013-08-06 08:07:16,725 DEBUG [agent.transport.Request] (Job-Executor-28:job-27
= [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Seq 3-1317535777: Received: { Ans:
, MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2013-08-06 08:07:16,780 DEBUG [agent.transport.Request] (Job-Executor-28:job-27
= [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Seq 3-1317535778: Sending { Cmd ,
MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3b18f8e5-e7e9-4658-9a85-a58275d1fbef","volumeType":"DATADISK","dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_esx_os","_role":"ImageCache"}},"name":"cent53-upload","size":459320832,"path":"volumes/2/12/24998551-bab1-4b9c-864c-cdcc23b21a3c.ova","volumeId":12,"accountId":2,"format":"OVA","id":12,"hypervisorType":"None"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"3b18f8e5-e7e9-4658-9a85-a58275d1fbef","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"b845e7d4-562a-3b2d-8e59-b1df565f99e5","id":1,"poolType":"VMFS","host":"VMFS
datastore:
/sanjeev/openFiler","path":"/sanjeev/openFiler","port":0}},"name":"cent53-upload","size":459320832,"volumeId":12,"accountId":2,"format":"OVA","id":12,"hypervisorType":"None"}},"executeInSequence":false,"wait":10800}}]
}
2013-08-06 08:09:24,002 DEBUG [agent.transport.Request]
(AgentManager-Handler-14:null) Seq 3-1317535778: Processing: { Ans: , MgmtId:
6615759585382, via: 3, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"path":"d093eb32a65a49e08e8237edac6772c9","accountId":0,"id":0}},"result":true,"wait":0}}]
}
2013-08-06 08:09:24,002 DEBUG [agent.transport.Request] (Job-Executor-28:job-27
= [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Seq 3-1317535778: Received: { Ans:
, MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2013-08-06 08:09:24,030 DEBUG [db.Transaction.Transaction]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Rolling
back the transaction: Time = 2 Name =
-AsyncJobManagerImpl$1.run:494-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679;
called by
-Transaction.rollback:896-Transaction.removeUpTo:839-Transaction.close:663-TransactionContextBuilder.interceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:133-GenericDaoBase.update:774-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-GenericDaoBase.update:1262-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VolumeObject.processEvent:476-VolumeServiceImpl.copyVolumeFromImageToPrimaryCallback:689-NativeMethodAccessorImpl.invoke0:-2
2013-08-06 08:09:24,033 DEBUG [cloud.storage.VolumeManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) copy volume
failed: com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@53b69b6d: UPDATE volumes SET
volumes.path=_binary'd093eb32a65a49e08e8237edac6772c9', volumes.pool_id=1,
volumes.size=null WHERE volumes.id = 12
2013-08-06 08:09:24,042 ERROR [cloud.async.AsyncJobManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Unexpected
exception while executing
org.apache.cloudstack.api.command.user.volume.AttachVolumeCmd
com.cloud.utils.exception.CloudRuntimeException: copy volume failed:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@53b69b6d: UPDATE volumes SET
volumes.path=_binary'd093eb32a65a49e08e8237edac6772c9', volumes.pool_id=1,
volumes.size=null WHERE volumes.id = 12
at
com.cloud.storage.VolumeManagerImpl.copyVolumeFromSecToPrimary(VolumeManagerImpl.java:634)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.storage.VolumeManagerImpl.copyVolume(VolumeManagerImpl.java:1501)
at
com.cloud.storage.VolumeManagerImpl.createVolumeOnPrimaryStorage(VolumeManagerImpl.java:1532)
at
com.cloud.storage.VolumeManagerImpl.attachVolumeToVM(VolumeManagerImpl.java:1829)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.volume.AttachVolumeCmd.execute(AttachVolumeCmd.java:122)
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-06 08:09:24,046 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-28:job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ]) Complete
async job-27 = [ 1a25a5ce-76b8-4dd4-be82-2723a91daff6 ], jobStatus: 2,
resultCode: 530, result: Error Code: 530 Error text: copy volume failed:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@53b69b6d: UPDATE volumes SET
volumes.path=_binary'd093eb32a65a49e08e8237edac6772c9', volumes.pool_id=1,
volumes.size=null WHERE volumes.id = 12
In volumes table state remains in "Copying" state for this volume.
Attaching management server log file and cloud DB.
--
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
