Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id E987CFC12 for ; Tue, 6 Aug 2013 10:53:56 +0000 (UTC) Received: (qmail 59959 invoked by uid 500); 6 Aug 2013 10:53:53 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 59926 invoked by uid 500); 6 Aug 2013 10:53:52 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 59880 invoked by uid 500); 6 Aug 2013 10:53:51 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 59856 invoked by uid 99); 6 Aug 2013 10:53:50 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 06 Aug 2013 10:53:50 +0000 Date: Tue, 6 Aug 2013 10:53:50 +0000 (UTC) From: "Abhinav Roy (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-4002) [Upgrade][2.2.16 to 4.2] After upgrade creation of volume from a snapshot which was existing before upgrade, fails with NPE MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-4002?page=3Dcom.atl= assian.jira.plugin.system.issuetabpanels:all-tabpanel ] Abhinav Roy updated CLOUDSTACK-4002: ------------------------------------ Attachment: CS4002.zip All the log files and db dumps are in CS4002.zip =20 > [Upgrade][2.2.16 to 4.2] After upgrade creation of volume from a snapshot= which was existing before upgrade, fails with NPE > -------------------------------------------------------------------------= -------------------------------------------------- > > Key: CLOUDSTACK-4002 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-400= 2 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Snapshot, Storage Controller, Upgrade > Affects Versions: 4.2.0 > Environment: upgraded environment from 2.2.16 to 4.2 > Hypervisor : XEN 6.0.2 > Reporter: Abhinav Roy > Assignee: Min Chen > Priority: Critical > Fix For: 4.2.0 > > Attachments: apilog.log, Bforeupgraedecloud-backup.dmp, CS4002.zi= p, DB_DUMP_2216_cloud-31jul.sql, DB_DUMP_420_cloud-1Aug.sql, management-ser= ver.log, postupgradecloud-backup.dmp > > > Steps : > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > 1. Deploy CS advanced zone setup with Xen 6.0.2 hypervisor > 2. Create VMs. v1, v2 > 3. Create snapshots on the ROOT volumes of the VMs created in step2 , s1,= s2 > 4. Upgrade CS to 4.2 > 5. Now try to create volumes from snapshots s1/s2 > Expected behaviour : > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > Creation of volumes should be successful. > Observed behaviour : > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D > 1. The volume creation fails with NPE and gets stuck in "creating" in the= DB > 2013-08-01 13:25:18,846 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:nu= ll) =3D=3D=3DSTART=3D=3D=3D 10.144.7.7 -- GET command=3DcreateVolume&resp= onse=3Djson&sessionkey=3De6y2vkO969W8moD6GKiQkvMwjA8%3D&sna > pshotid=3D2&name=3Dvol-root5+au+from+snapshot&_=3D1375343509092 > 2013-08-01 13:25:18,967 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina= -exec-22:null) submit async job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef08= 23 ], details: AsyncJobVO {id:39, userId: 2, accountId: 2, sessionKey: null= , instanceType: Volume, instanceId: 18, cmd: org.apache.cloudstack.api.comm= and.user.volume.CreateVolumeCmd, cmdOriginator: null, cmdInfo: {"id":"18","= response":"json","sessionkey":"e6y2vkO969W8moD6GKiQkvMwjA8\u003d","cmdEvent= Type":"VOLUME.CREATE","ctxUserId":"2","snapshotid":"2","name":"vol-root5 au= from snapshot","httpmethod":"GET","_":"1375343509092","ctxAccountId":"2","= ctxStartEventId":"157"}, cmdVersion: 0, callbackType: 0, callbackAddress: n= ull, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 22= 6870599129537, completeMsid: null, lastUpdated: null, lastPolled: null, cre= ated: null}2013-08-01 13:25:18,969 DEBUG [cloud.api.ApiServlet] (catalina-e= xec-22:null) =3D=3D=3DEND=3D=3D=3D 10.144.7.7 -- GET command=3DcreateVolu= me&response=3Djson&sessionkey=3De6y2vkO969W8moD6GKiQkvMwjA8%3D&snaps > hotid=3D2&name=3Dvol-root5+au+from+snapshot&_=3D1375343509092 > 2013-08-01 13:25:18,971 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Exec= utor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) Executing org.= apache.cloudstack.api.command.user.volume.C > reateVolumeCmd for job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ] > 2013-08-01 13:25:18,990 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-13:null) SeqA 4-10114: Processing Seq 4-10114: { Cmd , MgmtId:= -1, via: 4, Ver: v1, Flags: 11, [{"com.c > loud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo"= :"{\n \"connections\": []\n}","wait":0}}] } > 2013-08-01 13:25:19,001 DEBUG [agent.manager.AgentManagerImpl] (AgentMana= ger-Handler-13:null) SeqA 4-10114: Sending Seq 4-10114: { Ans: , MgmtId: 2= 26870599129537, via: 4, Ver: v1, Flags: 1 > 00010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0= }}] } > 2013-08-01 13:25:19,019 DEBUG [storage.allocator.LocalStoragePoolAllocato= r] (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) Lo= calStoragePoolAllocator trying to find stor > age pool to fit the vm > 2013-08-01 13:25:19,019 DEBUG [storage.allocator.ClusterScopeStoragePoolA= llocator] (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef082= 3 ]) ClusterScopeStoragePoolAllocator looki > ng for storage pool > 2013-08-01 13:25:19,020 DEBUG [storage.allocator.ClusterScopeStoragePoolA= llocator] (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef082= 3 ]) Looking for pools in dc: 1 pod:1 clu > ster:null > 2013-08-01 13:25:19,024 DEBUG [storage.allocator.AbstractStoragePoolAlloc= ator] (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ])= Checking if storage pool is suitable, name > : null ,poolId: 200 > 2013-08-01 13:25:19,029 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) Checking pool= 200 for storage, totalSize: 879609315328,=20 > usedBytes: 651471093760, usedPct: 0.7406368741298187, disable threshold: = 0.85 > 2013-08-01 13:25:19,055 DEBUG [cloud.storage.StorageManagerImpl] (Job-Exe= cutor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) Checking pool= : 200 for volume allocation [Vol[18|vm=3Dnull > |DATADISK]], maxSize : 1759218630656, totalAllocatedSize : 128773780480, = askingSize : 8589934592, allocated disable threshold: 0.85 > 2013-08-01 13:25:19,055 DEBUG [storage.allocator.ClusterScopeStoragePoolA= llocator] (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef082= 3 ]) FirstFitStoragePoolAllocator returning > 1 suitable storage pools > 2013-08-01 13:25:19,058 DEBUG [allocator.impl.UserConcentratedAllocator] = (Job-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) There= are no pods with enough memory/CPU capacit > y in zone zone-1 > 2013-08-01 13:25:19,080 DEBUG [storage.volume.VolumeServiceImpl] (Job-Exe= cutor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ]) create volume= from snapshot failed > java.lang.NullPointerException > at org.apache.cloudstack.storage.volume.VolumeServiceImpl.createV= olumeFromSnapshot(VolumeServiceImpl.java:567) at com.cloud.storage.V= olumeManagerImpl.createVolumeFromSnapshot(VolumeManagerImpl.java:552) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at com.cloud.storage.VolumeManagerImpl.createVolumeFromSnapshot(V= olumeManagerImpl.java:602) > at com.cloud.storage.VolumeManagerImpl.createVolume(VolumeManager= Impl.java:1046) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$= InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12= 5) > at com.cloud.storage.VolumeManagerImpl.createVolume(VolumeManager= Impl.java:180) > at org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd.= execute(CreateVolumeCmd.java:189) > 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(Exe= cutors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(Fu= tureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolEx= ecutor.java:1110) =20 > =09=09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:603) =20 > =09=09at java.lang.Thread.run(Thread.java:636) > =09=092013-08-01 13:25:19,080 DEBUG [cloud.storage.VolumeManagerImpl] (Jo= b-Executor-14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ])=20 > =09=09Failed to create volume from snapshot:java.lang.NullPointerExceptio= n2013-08-01=20 > =09=0913:25:19,080 DEBUG [cloud.storage.VolumeManagerImpl] (Job-Executor-= 14:job-39 =3D [ 31f14989-012d-414d-a0dd-a15232ef0823 ])=20 > =09=09Failed to create volume: 18=09com.cloud.utils.exception.CloudRuntim= eException: Failed to create volume from snapshot:java.lang.NullPointerExce= ption =20 > =09=09at com.cloud.storage.VolumeManagerImpl.createVolumeFromSnapshot(Vol= umeManagerImpl.java:557) =20 > =09=09at com.cloud.utils.component.ComponentInstantiationPostProcessor$In= terceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)= =20 > =09=09at com.cloud.storage.VolumeManagerImpl.createVolumeFromSnapshot(Vol= umeManagerImpl.java:602) =20 > =09=09at com.cloud.storage.VolumeManagerImpl.createVolume(VolumeManagerIm= pl.java:1046) =20 > =09=09at com.cloud.utils.component.ComponentInstantiationPostProcessor$In= terceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)= =20 > =09=09at com.cloud.storage.VolumeManagerImpl.createVolume(VolumeManagerIm= pl.java:180) =20 > =09=09at org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd.ex= ecute(CreateVolumeCmd.java:189) =20 > =09=09at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158) = =20 > =09=09at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.ja= va:531) =20 > =09=09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.ja= va:471) =20 > =09=09at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:33= 4) =20 > =09=09at java.util.concurrent.FutureTask.run(FutureTask.java:166) = =20 > =09=09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExec= utor.java:1110) =20 > =09=09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExe= cutor.java:603) =20 > =09=09at java.lang.Thread.run(Thread.java:636)2013-08-01 13:25:19,113 DEB= UG [cloud.async.AsyncJobManagerImpl] (Job-Executor-14:job-39 =3D [ 31f14989= -012d-414d-a0dd-a15232ef0823 ]) Complete async job-39 =3D [ 31f14989-012d-4= 14d-a0dd-a15232ef0823 ], jobStatus: 2, resultCode: 530, result: Error Code:= 530 Error text: Failed to create a volume2013-08-01 13:25:22,005 DEBUG [cl= oud.api.ApiServlet] (catalina-exec-1:null) =3D=3D=3DSTART=3D=3D=3D 10.144.= 7.7 -- GET command=3DqueryAsyncJobResult&jobId=3D31f14989-012d-414d-a0dd-a= 15232ef0823&response=3Djson&sessionkey=3De6y2vkO969W8moD6GKiQkvMwjA8%3D&_= =3D13753435122972013-08-01 13:25:22,017 DEBUG [cloud.async.AsyncJobManagerI= mpl] (catalina-exec-1:null) Async job-39 =3D [ 31f14989-012d-414d-a0dd-a152= 32ef0823 ] completed > mysql> select * from volumes where id=3D18; > +----+------------+-----------+---------+-------------+-----------+------= ----------------------+------------+--------+------+--------+--------------= --+------------+---------+-------------+-----------+------------------+----= ---------+--------+----------------------------+-------------+-------------= --------+----------+---------------------+---------+----------+------------= +--------------------------------------+--------------+--------------+-----= ------+----------------+--------+----------+----------+--------------------= ----+ > | id | account_id | domain_id | pool_id | instance_id | device_id | name = | size | folder | path | pod_id | data_center_i= d | iscsi_name | host_ip | volume_type | pool_type | disk_offering_id | tem= plate_id | iso_id | first_snapshot_backup_uuid | recreatable | created = | attached | updated | removed | state | chain_info = | uuid | last_pool_id | update_count | disk= _type | display_volume | format | min_iops | max_iops | vm_snapshot_chain_s= ize | > +----+------------+-----------+---------+-------------+-----------+------= ----------------------+------------+--------+------+--------+--------------= --+------------+---------+-------------+-----------+------------------+----= ---------+--------+----------------------------+-------------+-------------= --------+----------+---------------------+---------+----------+------------= +--------------------------------------+--------------+--------------+-----= ------+----------------+--------+----------+----------+--------------------= ----+ > | 18 | 2 | 1 | NULL | NULL | NULL | vol-r= oot5 au from snapshot | 8589934592 | NULL | NULL | NULL | = 1 | NULL | NULL | DATADISK | NULL | 1 | = 2 | NULL | NULL | 0 | 2013-08-01 0= 7:55:18 | NULL | 2013-08-01 07:55:19 | NULL | Creating | NULL = | a2330e3b-b6b8-44cc-babd-aa28ef1baa95 | NULL | 1 | NULL= | 1 | NULL | NULL | NULL | N= ULL | > +----+------------+-----------+---------+-------------+-----------+------= ----------------------+------------+--------+------+--------+--------------= --+------------+---------+-------------+-----------+------------------+----= ---------+--------+----------------------------+-------------+-------------= --------+----------+---------------------+---------+----------+------------= +--------------------------------------+--------------+--------------+-----= ------+----------------+--------+----------+----------+--------------------= ----+ > 1 row in set (0.00 sec) > 2. If for the same Root volume I create another snapshot after upgrade , = and then create a volume from that snapshot then it succeeds. > mysql> select * from volumes where id=3D22; > +----+------------+-----------+---------+-------------+-----------+------= ----------------+------------+--------+------------------------------------= --+--------+----------------+------------+---------+-------------+---------= --+------------------+-------------+--------+----------------------------+-= ------------+---------------------+----------+---------------------+-------= --+-------+------------+--------------------------------------+------------= --+--------------+-----------+----------------+--------+----------+--------= --+------------------------+ > | id | account_id | domain_id | pool_id | instance_id | device_id | name = | size | folder | path = | pod_id | data_center_id | iscsi_name | host_ip | volume_type | pool_typ= e | disk_offering_id | template_id | iso_id | first_snapshot_backup_uuid | = recreatable | created | attached | updated | remove= d | state | chain_info | uuid | last_pool_i= d | update_count | disk_type | display_volume | format | min_iops | max_iop= s | vm_snapshot_chain_size | > +----+------------+-----------+---------+-------------+-----------+------= ----------------+------------+--------+------------------------------------= --+--------+----------------+------------+---------+-------------+---------= --+------------------+-------------+--------+----------------------------+-= ------------+---------------------+----------+---------------------+-------= --+-------+------------+--------------------------------------+------------= --+--------------+-----------+----------------+--------+----------+--------= --+------------------------+ > | 22 | 2 | 1 | 200 | NULL | NULL | vol f= rom snap root-5 | 8589934592 | NULL | a1eaaabd-19a9-48d8-9624-c9ee81ca01c= 9 | NULL | 1 | NULL | NULL | DATADISK | NULL = | 1 | 2 | NULL | NULL | = 0 | 2013-08-01 08:10:53 | NULL | 2013-08-01 08:11:26 | NULL = | Ready | NULL | 840077f9-0840-41b2-a4e0-de35a06ada37 | NUL= L | 2 | NULL | 1 | NULL | NULL | NUL= L | NULL | > +----+------------+-----------+---------+-------------+-----------+------= ----------------+------------+--------+------------------------------------= --+--------+----------------+------------+---------+-------------+---------= --+------------------+-------------+--------+----------------------------+-= ------------+---------------------+----------+---------------------+-------= --+-------+------------+--------------------------------------+------------= --+--------------+-----------+----------------+--------+----------+--------= --+------------------------+ > 1 row in set (0.00 sec) -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs For more information on JIRA, see: http://www.atlassian.com/software/jira