You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "edison su (JIRA)" <ji...@apache.org> on 2014/11/25 21:24:14 UTC
[jira] [Commented] (CLOUDSTACK-7960) [Automation] Creation of
Volume from Snapshot fails due to StringIndexOutOfBoundsException
[ https://issues.apache.org/jira/browse/CLOUDSTACK-7960?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14225149#comment-14225149 ]
edison su commented on CLOUDSTACK-7960:
---------------------------------------
simulator bug, koushik can take a look at it?
> [Automation] Creation of Volume from Snapshot fails due to StringIndexOutOfBoundsException
> ------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-7960
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7960
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Automation
> Affects Versions: 4.5.0
> Reporter: Chandan Purushothama
> Assignee: Koushik Das
> Priority: Critical
> Fix For: 4.5.0
>
>
> Use Case:
> Validate the following sequence
> # Deploy VM with custom disk offering and check the primary storage resource count
> # Stop the VM and create Snapshot from VM's volume
> # Create volume again from this snapshot
> StringIndexOutOfBoundsException:
> {noformat}
> 2014-11-21 01:04:06,153 DEBUG [c.c.a.ApiServlet] (catalina-exec-22:ctx-4e287cc2 ctx-e68b28dc ctx-a00dd9d4) ===END=== 10.220.135.118 -- GET account=test-a-TestVolumeLimits-test_create_template_snapshot_1_root_domain_admin-9B6G87&domainid=58f506ce-7108-11e4-bca3-7640e6bc0920&name=Test+Volume-DGE7AV&zoneid=7934f921-50e4-406b-b0dd-8c474907d8cf&apiKey=rRJabsdLiEc7Wnp7V6yxoQWckT_5EBLxkm5Bz5JFImYh-CqbkPW8fL87x8Qp2QDJXAobZscfqwwaW9jm3mXUzg&command=createVolume&signature=Kb4x7pXEbm2yfoNmKAVZ92bFu1Y%3D&snapshotid=cd663163-8045-43d1-9a88-899d0c1e9182&response=json&size=2
> 2014-11-21 01:04:06,158 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-662f483b) ===START=== 10.220.135.118 -- GET jobid=5b446f9d-2056-43f2-9057-2d16b40e926f&apiKey=rRJabsdLiEc7Wnp7V6yxoQWckT_5EBLxkm5Bz5JFImYh-CqbkPW8fL87x8Qp2QDJXAobZscfqwwaW9jm3mXUzg&command=queryAsyncJobResult&response=json&signature=dtw5FWz4%2FrigWTMJHLTB7vMCKS0%3D
> 2014-11-21 01:04:06,175 DEBUG [c.c.a.ApiServlet] (catalina-exec-5:ctx-662f483b ctx-ad395747 ctx-b176f4c5) ===END=== 10.220.135.118 -- GET jobid=5b446f9d-2056-43f2-9057-2d16b40e926f&apiKey=rRJabsdLiEc7Wnp7V6yxoQWckT_5EBLxkm5Bz5JFImYh-CqbkPW8fL87x8Qp2QDJXAobZscfqwwaW9jm3mXUzg&command=queryAsyncJobResult&response=json&signature=dtw5FWz4%2FrigWTMJHLTB7vMCKS0%3D
> 2014-11-21 01:04:06,185 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) LocalStoragePoolAllocator trying to find storage pool to fit the vm
> 2014-11-21 01:04:06,185 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) ClusterScopeStoragePoolAllocator looking for storage pool
> 2014-11-21 01:04:06,185 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Looking for pools in dc: 1 pod:1 cluster:null
> 2014-11-21 01:04:06,187 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Found pools matching tags: [Pool[1|NetworkFilesystem], Pool[2|NetworkFilesystem], Pool[3|NetworkFilesystem]]
> 2014-11-21 01:04:06,189 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Checking if storage pool is suitable, name: null ,poolId: 1
> 2014-11-21 01:04:06,191 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Storage pool null (1) does not supply IOPS capacity, assuming enough capacity
> 2014-11-21 01:04:06,193 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Checking pool 1 for storage, totalSize: 1099511627776, usedBytes: 0, usedPct: 0.0, disable threshold: 0.85
> 2014-11-21 01:04:06,197 DEBUG [c.c.s.StorageManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Checking pool: 1 for volume allocation [Vol[764|vm=null|DATADISK]], maxSize : 2199023255552, totalAllocatedSize : 200, askingSize : 2147483648, allocated disable threshold: 0.85
> 2014-11-21 01:04:06,197 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools
> 2014-11-21 01:04:06,198 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Found a suitable pool for create volume: 1
> 2014-11-21 01:04:06,214 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) copyAsync inspecting src type SNAPSHOT copyAsync inspecting dest type VOLUME
> 2014-11-21 01:04:06,225 DEBUG [c.c.a.t.Request] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Seq 2-8004303912720929589: Sending { Cmd , MgmtId: 130021121067296, via: 2(SimulatedAgent.69573596-c121-47ea-8e5e-53deda420c30), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"null/f6a7021b-d987-4797-9aea-ec8e50431aec","volume":{"uuid":"813b2038-1df8-424c-b0d8-e814794fd90b","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0bbd54fe-b348-3e3d-9b91-b453a21bc43a","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.6","path":"/export/home/sandbox/primary2","port":2049,"url":"NetworkFilesystem://10.147.28.6/export/home/sandbox/primary2/?ROLE=Primary&STOREUUID=0bbd54fe-b348-3e3d-9b91-b453a21bc43a"}},"name":"DATA-725","size":2147483648,"path":"DATA-725","volumeId":762,"vmName":"i-526-725-QA","accountId":526,"provisioningType":"THIN","id":762,"deviceId":1,"hypervisorType":"Simulator"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.6:/export/home/sandbox/secondary","_role":"Image"}},"vmName":"i-526-725-QA","name":"QA-20c5fed9-7d23-44f0-b5c7-fa52309451e9_DATA-725_20141121010400","hypervisorType":"Simulator","id":19,"quiescevm":false,"physicalSize":0}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a306c42a-359d-4343-892d-db019efbad94","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7c07ec9b-a3c6-3466-ab5a-f5669ead0b22","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.6","path":"/export/home/sandbox/primary0","port":2049,"url":"NetworkFilesystem://10.147.28.6/export/home/sandbox/primary0/?ROLE=Primary&STOREUUID=7c07ec9b-a3c6-3466-ab5a-f5669ead0b22"}},"name":"Test Volume-DGE7AV","size":2147483648,"volumeId":764,"accountId":526,"provisioningType":"THIN","id":764,"hypervisorType":"Simulator"}},"executeInSequence":true,"options":{},"wait":10800}}] }
> 2014-11-21 01:04:06,225 DEBUG [c.c.a.t.Request] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Seq 2-8004303912720929589: Executing: { Cmd , MgmtId: 130021121067296, via: 2(SimulatedAgent.69573596-c121-47ea-8e5e-53deda420c30), Ver: v1, Flags: 100111, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"null/f6a7021b-d987-4797-9aea-ec8e50431aec","volume":{"uuid":"813b2038-1df8-424c-b0d8-e814794fd90b","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"0bbd54fe-b348-3e3d-9b91-b453a21bc43a","id":3,"poolType":"NetworkFilesystem","host":"10.147.28.6","path":"/export/home/sandbox/primary2","port":2049,"url":"NetworkFilesystem://10.147.28.6/export/home/sandbox/primary2/?ROLE=Primary&STOREUUID=0bbd54fe-b348-3e3d-9b91-b453a21bc43a"}},"name":"DATA-725","size":2147483648,"path":"DATA-725","volumeId":762,"vmName":"i-526-725-QA","accountId":526,"provisioningType":"THIN","id":762,"deviceId":1,"hypervisorType":"Simulator"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.6:/export/home/sandbox/secondary","_role":"Image"}},"vmName":"i-526-725-QA","name":"QA-20c5fed9-7d23-44f0-b5c7-fa52309451e9_DATA-725_20141121010400","hypervisorType":"Simulator","id":19,"quiescevm":false,"physicalSize":0}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"a306c42a-359d-4343-892d-db019efbad94","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"7c07ec9b-a3c6-3466-ab5a-f5669ead0b22","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.6","path":"/export/home/sandbox/primary0","port":2049,"url":"NetworkFilesystem://10.147.28.6/export/home/sandbox/primary0/?ROLE=Primary&STOREUUID=7c07ec9b-a3c6-3466-ab5a-f5669ead0b22"}},"name":"Test Volume-DGE7AV","size":2147483648,"volumeId":764,"accountId":526,"provisioningType":"THIN","id":764,"hypervisorType":"Simulator"}},"executeInSequence":true,"options":{},"wait":10800}}] }
> 2014-11-21 01:04:06,225 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-66:ctx-080426f7) Seq 2-8004303912720929589: Executing request
> 2014-11-21 01:04:06,238 ERROR [c.c.a.m.SimulatorManagerImpl] (DirectAgent-66:ctx-080426f7) Failed execute cmd:
> java.lang.StringIndexOutOfBoundsException: String index out of range: -1
> at java.lang.String.substring(String.java:1958)
> at java.lang.String.substring(String.java:1925)
> at com.cloud.resource.SimulatorStorageProcessor.createVolumeFromSnapshot(SimulatorStorageProcessor.java:213)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:97)
> at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:53)
> at com.cloud.agent.manager.SimulatorManagerImpl.simulate(SimulatorManagerImpl.java:421)
> at com.cloud.resource.AgentRoutingResource.executeRequestInContext(AgentRoutingResource.java:98)
> at com.cloud.resource.AgentResourceBase$1.runInContext(AgentResourceBase.java:254)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at com.cloud.resource.AgentResourceBase.executeRequest(AgentResourceBase.java:251)
> at com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:304)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> 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.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292)
> 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:722)
> 2014-11-21 01:04:06,239 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-66:ctx-080426f7) Seq 2-8004303912720929589: Response Received:
> 2014-11-21 01:04:06,239 DEBUG [c.c.a.t.Request] (DirectAgent-66:ctx-080426f7) Seq 2-8004303912720929589: Processing: { Ans: , MgmtId: 130021121067296, via: 2, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":false,"details":"java.lang.StringIndexOutOfBoundsException: String index out of range: -1","wait":0}}] }
> 2014-11-21 01:04:06,239 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-66:ctx-080426f7) Seq 2-8004303912720929589: No more commands found
> 2014-11-21 01:04:06,239 DEBUG [c.c.a.t.Request] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Seq 2-8004303912720929589: Received: { Ans: , MgmtId: 130021121067296, via: 2, Ver: v1, Flags: 110, { Answer } }
> 2014-11-21 01:04:06,244 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@1f6c7aa5), no need to delete from object in store ref table
> 2014-11-21 01:04:06,248 WARN [o.a.c.s.d.ObjectInDataStoreManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Snapshot 19 is not found on image store 1, so no need to delete
> 2014-11-21 01:04:06,248 DEBUG [o.a.c.e.o.VolumeOrchestrator] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Failed to create volume from snapshot:java.lang.StringIndexOutOfBoundsException: String index out of range: -1
> 2014-11-21 01:04:06,262 DEBUG [c.c.u.AccountManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276 ctx-db279945) Access granted to Acct[7f78b85e-7108-11e4-bca3-7640e6bc0920-admin] to Domain:1/ by AffinityGroupAccessChecker
> 2014-11-21 01:04:06,273 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-101:ctx-c66892e0 job-4276) Unexpected exception while executing org.apache.cloudstack.api.command.admin.volume.CreateVolumeCmdByAdmin
> com.cloud.utils.exception.CloudRuntimeException: Failed to create volume: 764
> at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:671)
> at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:157)
> at sun.reflect.GeneratedMethodAccessor841.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:106)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:51)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
> at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> at $Proxy185.createVolume(Unknown Source)
> at org.apache.cloudstack.api.command.admin.volume.CreateVolumeCmdByAdmin.execute(CreateVolumeCmdByAdmin.java:42)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:141)
> at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:108)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:536)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:493)
> 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:722)
> Caused by: com.cloud.utils.exception.CloudRuntimeException: Failed to create volume from snapshot:java.lang.StringIndexOutOfBoundsException: String index out of range: -1
> at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeFromSnapshot(VolumeOrchestrator.java:386)
> at com.cloud.storage.VolumeApiServiceImpl.createVolumeFromSnapshot(VolumeApiServiceImpl.java:693)
> at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:643)
> ... 31 more
> 2014-11-21 01:04:06,275 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Complete async job-4276, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":530,"errortext":"Failed to create volume: 764"}
> 2014-11-21 01:04:06,276 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Publish async job-4276 complete on message bus
> 2014-11-21 01:04:06,276 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Wake up jobs related to job-4276
> 2014-11-21 01:04:06,276 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Update db status for job-4276
> 2014-11-21 01:04:06,277 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Wake up jobs joined with job-4276 and disjoin all subjobs created from job- 4276
> 2014-11-21 01:04:06,279 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-c66892e0 job-4276) Done executing org.apache.cloudstack.api.command.admin.volume.CreateVolumeCmdByAdmin for job-4276
> 2014-11-21 01:04:06,279 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-101:ctx-c66892e0 job-4276) Remove job-4276 from job monitoring
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)