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 8ABB4D000 for ; Wed, 10 Dec 2014 13:47:13 +0000 (UTC) Received: (qmail 45546 invoked by uid 500); 10 Dec 2014 13:47:13 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 45515 invoked by uid 500); 10 Dec 2014 13:47:13 -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 45506 invoked by uid 500); 10 Dec 2014 13:47:13 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 45503 invoked by uid 99); 10 Dec 2014 13:47:13 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 10 Dec 2014 13:47:13 +0000 Date: Wed, 10 Dec 2014 13:47:13 +0000 (UTC) From: "Abhinandan Prateek (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (CLOUDSTACK-8014) Failed to create a volume from snapshot - Discrepency in the resource count ? 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-8014?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId= =3D14241090#comment-14241090 ]=20 Abhinandan Prateek commented on CLOUDSTACK-8014: ------------------------------------------------ If you try to delete the template twice, (maybe due to some race condition = it pops up in the UI while it is being deleted), then you get the resource = count issue: .. INFO [c.c.t.HypervisorTemplateAdapter] (Job-Executor-5:ctx-07a5e482 ctx-e4= 966196) Delete template from image store: secone INFO [c.c.t.HypervisorTemplateAdapter] (Job-Executor-5:ctx-07a5e482 ctx-e4= 966196) Delete template from image store: sectwo .. INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-6:ctx-fdf72fb9) Add job-1= 89 into job monitoring INFO [c.c.t.HypervisorTemplateAdapter] (Job-Executor-6:ctx-fdf72fb9 ctx-1e= 235c0f) Unable to find image store still having template: centos, so just m= ark the template removed INFO [c.c.r.ResourceLimitManagerImpl] (Job-Executor-6:ctx-fdf72fb9 ctx-1e2= 35c0f) Discrepency in the resource count (original count=3D46513518080 corr= ect count =3D 3563845120) for type secondary_storage for account ID 2 is fi= xed during resource count recalculation. INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor-6:ctx-fdf72fb9) Remove jo= b-189 from job monitoring ... This is just a info message and not a bug. > Failed to create a volume from snapshot - Discrepency in the resource cou= nt ? > -------------------------------------------------------------------------= ---- > > Key: CLOUDSTACK-8014 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-801= 4 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the defa= ult.)=20 > Components: Management Server > Affects Versions: 4.3.1 > Reporter: France > > As sent to mailing list: > Hi all. > We are on XS 6.0.2+Hotfixes and CS 4.3.1. > (All errors we are getting nowadays have come up only after upgrade from = 4.1.1, 4.1.1 worked perfectly.) > After successfully creating s snapshot, I want to create a volume from it= , so it can be downloaded offsite. > After clicking =E2=80=9CCreate volume=E2=80=9D I get an error Failed to c= reate a volume. > If i got to list of volumes, there is a volume with name as defined, but = Status is empty, and only buttons for attach and destroy exist. > I have taken a look at catalina.out and management-server.log. Here is th= e log detailing a failure. > Can you see the problem? How should I fix it? Please advise me. > Should I create a bug report? > I have also manually checked space on all storages and it seems there is = LOTS of free space. Resources based on CS Web GUI are: > Primary Storage Allocated 15% > Secondary Storage 5% > 2014-12-03 12:20:42,493 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consolepro= xy-1:ctx-2d51baa2) Zone 1 is ready to launch console proxy > 2014-12-03 12:20:42,580 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secs= torage-1:ctx-53354d18) Zone 1 is ready to launch secondary storage VM > 2014-12-03 12:20:42,894 DEBUG [c.c.a.ApiServlet] (http-6443-exec-108:ctx-= a228ce49) =3D=3D=3DSTART=3D=3D=3D 111.client.ip.111 -- GET command=3DlistZ= ones&available=3Dtrue&response=3Djson&sessionkey=3DCENSORED%3D&_=3D14176058= 14964 > 2014-12-03 12:20:42,909 DEBUG [c.c.a.ApiServlet] (http-6443-exec-108:ctx-= a228ce49 ctx-74e696ca) =3D=3D=3DEND=3D=3D=3D 111.client.ip.111 -- GET comma= nd=3DlistZones&available=3Dtrue&response=3Djson&sessionkey=3DCENSORED%3D&_= =3D1417605814964 > 2014-12-03 12:20:46,482 DEBUG [c.c.a.ApiServlet] (http-6443-exec-107:ctx-= 4a28e57c) =3D=3D=3DSTART=3D=3D=3D 111.client.ip.111 -- GET command=3Dcreat= eVolume&response=3Djson&sessionkey=3DCENSORED%3D&snapshotid=3D49e4bba9-844d= -4b7b-aca2-95a318f17dc4&name=3Dtestbrisi567&_=3D1417605818552 > 2014-12-03 12:20:46,490 DEBUG [c.c.u.AccountManagerImpl] (http-6443-exec-= 107:ctx-4a28e57c ctx-d7a11540) Access to Acct[7d6da3bc-0d70-44eb-8a70-422e4= eea184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-user= Name] by DomainChecker > 2014-12-03 12:20:46,494 DEBUG [c.c.u.AccountManagerImpl] (http-6443-exec-= 107:ctx-4a28e57c ctx-d7a11540) Access to Acct[7d6da3bc-0d70-44eb-8a70-422e4= eea184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-user= Name] by DomainChecker > 2014-12-03 12:20:46,507 DEBUG [c.c.u.AccountManagerImpl] (http-6443-exec-= 107:ctx-4a28e57c ctx-d7a11540) Access to com.cloud.storage.SnapshotVO$$Enha= ncerByCGLIB$$3490cea0@60c95391 granted to Acct[7d6da3bc-0d70-44eb-8a70-422e= 4eea184e-userName] by DomainChecker > 2014-12-03 12:20:46,571 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor= -166:ctx-d915e890) Add job-2804 into job monitoring > 2014-12-03 12:20:46,571 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Exec= utor-166:ctx-d915e890) Executing AsyncJobVO {id:2804, userId: 59, accountId= : 60, instanceType: Volume, instanceId: 617, cmd: org.apache.cloudstack.api= .command.user.volume.CreateVolumeCmd, cmdInfo: {"id":"617","response":"json= ","sessionkey":"CENSORED\u003d","cmdEventType":"VOLUME.CREATE","ctxUserId":= "59","snapshotid":"49e4bba9-844d-4b7b-aca2-95a318f17dc4","name":"testbrisi5= 67","httpmethod":"GET","_":"1417605818552","ctxAccountId":"60","ctxStartEve= ntId":"62488"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resul= tCode: 0, result: null, initMsid: 95545481387, completeMsid: null, lastUpda= ted: null, lastPolled: null, created: null} > 2014-12-03 12:20:46,577 DEBUG [c.c.u.AccountManagerImpl] (Job-Executor-16= 6:ctx-d915e890 ctx-d7a11540) Access to Acct[7d6da3bc-0d70-44eb-8a70-422e4ee= a184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-userNa= me] by DomainChecker > 2014-12-03 12:20:46,578 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (http-644= 3-exec-107:ctx-4a28e57c ctx-d7a11540) submit async job-2804, details: Async= JobVO {id:2804, userId: 59, accountId: 60, instanceType: Volume, instanceId= : 617, cmd: org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd, = cmdInfo: {"id":"617","response":"json","sessionkey":"CENSORED\u003d","cmdEv= entType":"VOLUME.CREATE","ctxUserId":"59","snapshotid":"49e4bba9-844d-4b7b-= aca2-95a318f17dc4","name":"testbrisi567","httpmethod":"GET","_":"1417605818= 552","ctxAccountId":"60","ctxStartEventId":"62488"}, cmdVersion: 0, status:= IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 9554= 5481387, completeMsid: null, lastUpdated: null, lastPolled: null, created: = null} > 2014-12-03 12:20:46,580 DEBUG [c.c.a.ApiServlet] (http-6443-exec-107:ctx-= 4a28e57c ctx-d7a11540) =3D=3D=3DEND=3D=3D=3D 111.client.ip.111 -- GET comm= and=3DcreateVolume&response=3Djson&sessionkey=3DCENSORED%3D&snapshotid=3D49= e4bba9-844d-4b7b-aca2-95a318f17dc4&name=3Dtestbrisi567&_=3D1417605818552 > 2014-12-03 12:20:46,608 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Job-= Executor-166:ctx-d915e890 ctx-d7a11540) LocalStoragePoolAllocator trying to= find storage pool to fit the vm > 2014-12-03 12:20:46,608 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) ClusterScopeStoragePoolAlloc= ator looking for storage pool > 2014-12-03 12:20:46,608 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Looking for pools in dc: 1 = pod:1 cluster:null having tags:[HAiscsi2] > 2014-12-03 12:20:46,610 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Found pools matching tags: [= Pool[208|IscsiLUN], Pool[209|IscsiLUN]] > 2014-12-03 12:20:46,612 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Adding pool Pool[206|IscsiLU= N] to avoid set since it did not match tags > 2014-12-03 12:20:46,612 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Adding pool Pool[207|IscsiLU= N] to avoid set since it did not match tags > 2014-12-03 12:20:46,612 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Adding pool Pool[210|Network= Filesystem] to avoid set since it did not match tags > 2014-12-03 12:20:46,612 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Removing pool Pool[208|Iscsi= LUN] from avoid set, must have been inserted when searching for another dis= k's tag > 2014-12-03 12:20:46,612 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator= ] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Removing pool Pool[209|Iscsi= LUN] from avoid set, must have been inserted when searching for another dis= k's tag > 2014-12-03 12:20:46,614 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (J= ob-Executor-166:ctx-d915e890 ctx-d7a11540) Checking if storage pool is suit= able, name: null ,poolId: 208 > 2014-12-03 12:20:46,617 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-16= 6:ctx-d915e890 ctx-d7a11540) Checking pool 208 for storage, totalSize: 1520= 242262016, usedBytes: 865985363968, usedPct: 0.569636422828828, disable thr= eshold: 0.95 > 2014-12-03 12:20:46,622 DEBUG [c.c.s.VolumeApiServiceImpl] (Job-Executor-= 166:ctx-d915e890 ctx-d7a11540) Failed to create volume: 617 > java.lang.NullPointerException > =09at com.cloud.storage.StorageManagerImpl.storagePoolHasEnoughSpace(Stor= ageManagerImpl.java:1570) > =09at org.apache.cloudstack.storage.allocator.AbstractStoragePoolAllocato= r.filter(AbstractStoragePoolAllocator.java:199) > =09at org.apache.cloudstack.storage.allocator.ClusterScopeStoragePoolAllo= cator.select(ClusterScopeStoragePoolAllocator.java:110) > =09at org.apache.cloudstack.storage.allocator.AbstractStoragePoolAllocato= r.allocateToPool(AbstractStoragePoolAllocator.java:109) > =09at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.findS= toragePool(VolumeOrchestrator.java:256) > =09at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.creat= eVolumeFromSnapshot(VolumeOrchestrator.java:339) > =09at com.cloud.storage.VolumeApiServiceImpl.createVolumeFromSnapshot(Vol= umeApiServiceImpl.java:785) > =09at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServic= eImpl.java:735) > =09at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServic= eImpl.java:177) > =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImp= l.java:57) > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcc= essorImpl.java:43) > =09at java.lang.reflect.Method.invoke(Method.java:622) > =09at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflec= tion(AopUtils.java:317) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.invoke= Joinpoint(ReflectiveMethodInvocation.java:183) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.procee= d(ReflectiveMethodInvocation.java:150) > =09at com.cloud.event.ActionEventInterceptor.invoke(ActionEventIntercepto= r.java:50) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.procee= d(ReflectiveMethodInvocation.java:161) > =09at org.springframework.aop.interceptor.ExposeInvocationInterceptor.inv= oke(ExposeInvocationInterceptor.java:91) > =09at org.springframework.aop.framework.ReflectiveMethodInvocation.procee= d(ReflectiveMethodInvocation.java:172) > =09at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDyna= micAopProxy.java:204) > =09at com.sun.proxy.$Proxy196.createVolume(Unknown Source) > =09at org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd.execu= te(CreateVolumeCmd.java:196) > =09at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161) > =09at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDisp= atcher.java:109) > =09at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.jav= a:66) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.= call(DefaultManagedContext.java:56) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ca= llWithContext(DefaultManagedContext.java:103) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ru= nWithContext(DefaultManagedContext.java:53) > =09at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.ja= va:63) > =09at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run= InContext(AsyncJobManagerImpl.java:509) > =09at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(= ManagedContextRunnable.java:49) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.= call(DefaultManagedContext.java:56) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ca= llWithContext(DefaultManagedContext.java:103) > =09at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.ru= nWithContext(DefaultManagedContext.java:53) > =09at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Ma= nagedContextRunnable.java:46) > =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:= 471) > =09at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > =09at java.util.concurrent.FutureTask.run(FutureTask.java:166) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1146) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:701) > 2014-12-03 12:20:46,631 DEBUG [c.c.u.AccountManagerImpl] (Job-Executor-16= 6:ctx-d915e890 ctx-d7a11540) Access granted to Acct[7d6da3bc-0d70-44eb-8a70= -422e4eea184e-userName] to Domain:10/public/ by AffinityGroupAccessChecker > 2014-12-03 12:20:46,635 INFO [c.c.r.ResourceLimitManagerImpl] (Job-Execu= tor-166:ctx-d915e890 ctx-d7a11540) Discrepency in the resource count (origi= nal count=3D107374182400 correct count =3D 85899345920) for type primary_st= orage for account ID 60 is fixed during resource count recalculation. > 2014-12-03 12:20:46,651 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Exec= utor-166:ctx-d915e890) Complete async job-2804, jobStatus: FAILED, resultCo= de: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/= {"uuidList":[],"errorcode":530,"errortext":"Failed to create a volume"} > 2014-12-03 12:20:46,657 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Job-Exec= utor-166:ctx-d915e890) Done executing org.apache.cloudstack.api.command.use= r.volume.CreateVolumeCmd for job-2804 > 2014-12-03 12:20:46,660 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Job-Executor= -166:ctx-d915e890) Remove job-2804 from job monitoring > 2014-12-03 12:20:49,618 DEBUG [c.c.a.ApiServlet] (http-6443-exec-95:ctx-3= aa7826a) =3D=3D=3DSTART=3D=3D=3D 111.client.ip.111 -- GET command=3DqueryA= syncJobResult&jobId=3Df943cc56-d7a8-4529-9990-1a3ee6e9a13d&response=3Djson&= sessionkey=3DCENSORED%3D&_=3D1417605821689 > 2014-12-03 12:20:49,689 DEBUG [c.c.a.ApiServlet] (http-6443-exec-95:ctx-3= aa7826a ctx-d76a1f77) =3D=3D=3DEND=3D=3D=3D 111.client.ip.111 -- GET comma= nd=3DqueryAsyncJobResult&jobId=3Df943cc56-d7a8-4529-9990-1a3ee6e9a13d&respo= nse=3Djson&sessionkey=3DCENSORED%3D&_=3D1417605821689 > 2014-12-03 12:20:50,015 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha= ndler-12:null) SeqA 27-839631: Processing Seq 27-839631: { Cmd , MgmtId: -= 1, via: 27, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadRepo= rtCommand":{"_proxyVmId":473,"_loadInfo":"{\n \"connections\": []\n}","wai= t":0}}] } > 2014-12-03 12:20:50,144 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Ha= ndler-12:null) SeqA 27-839631: Sending Seq 27-839631: { Ans: , MgmtId: 955= 45481387, via: 27, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentCont= rolAnswer":{"result":true,"wait":0}}] } > BTW there is a typo in the code, Discrepency should be DescrepAncy.=20 > Regards, > F. -- This message was sent by Atlassian JIRA (v6.3.4#6332)