[ https://issues.apache.org/jira/browse/CLOUDSTACK-4112?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Min Chen resolved CLOUDSTACK-4112. ---------------------------------- Resolution: Fixed > [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 > Assignee: Min Chen > 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