Failed to create a volume from snapshot CS 4.3.1 - Discrepency in the resource count ?

[France <ma...@isg.si>]

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 “Create volume” I get an error Failed to create 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 the 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] (consoleproxy-1:ctx-2d51baa2) Zone 1 is ready to launch console proxy
2014-12-03 12:20:42,580 DEBUG [c.c.s.s.SecondaryStorageManagerImpl] (secstorage-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) ===START===  111.client.ip.111 -- GET  command=listZones&available=true&response=json&sessionkey=CENSORED%3D&_=1417605814964
2014-12-03 12:20:42,909 DEBUG [c.c.a.ApiServlet] (http-6443-exec-108:ctx-a228ce49 ctx-74e696ca) ===END===  111.client.ip.111 -- GET  command=listZones&available=true&response=json&sessionkey=CENSORED%3D&_=1417605814964
2014-12-03 12:20:46,482 DEBUG [c.c.a.ApiServlet] (http-6443-exec-107:ctx-4a28e57c) ===START===  111.client.ip.111 -- GET  command=createVolume&response=json&sessionkey=CENSORED%3D&snapshotid=49e4bba9-844d-4b7b-aca2-95a318f17dc4&name=testbrisi567&_=1417605818552
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-422e4eea184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-userName] 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-422e4eea184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-userName] 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$$EnhancerByCGLIB$$3490cea0@60c95391 granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-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-Executor-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":"testbrisi567","httpmethod":"GET","_":"1417605818552","ctxAccountId":"60","ctxStartEventId":"62488"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 95545481387, completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-12-03 12:20:46,577 DEBUG [c.c.u.AccountManagerImpl] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Access to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-userName] granted to Acct[7d6da3bc-0d70-44eb-8a70-422e4eea184e-userName] by DomainChecker
2014-12-03 12:20:46,578 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (http-6443-exec-107:ctx-4a28e57c ctx-d7a11540) submit async job-2804, details: 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":"testbrisi567","httpmethod":"GET","_":"1417605818552","ctxAccountId":"60","ctxStartEventId":"62488"}, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 95545481387, 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) ===END===  111.client.ip.111 -- GET  command=createVolume&response=json&sessionkey=CENSORED%3D&snapshotid=49e4bba9-844d-4b7b-aca2-95a318f17dc4&name=testbrisi567&_=1417605818552
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) ClusterScopeStoragePoolAllocator 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|IscsiLUN] 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|IscsiLUN] 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|NetworkFilesystem] 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|IscsiLUN] from avoid set, must have been inserted when searching for another disk'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|IscsiLUN] from avoid set, must have been inserted when searching for another disk's tag
2014-12-03 12:20:46,614 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Checking if storage pool is suitable, name: null ,poolId: 208
2014-12-03 12:20:46,617 DEBUG [c.c.s.StorageManagerImpl] (Job-Executor-166:ctx-d915e890 ctx-d7a11540) Checking pool 208 for storage, totalSize: 1520242262016, usedBytes: 865985363968, usedPct: 0.569636422828828, disable threshold: 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
	at com.cloud.storage.StorageManagerImpl.storagePoolHasEnoughSpace(StorageManagerImpl.java:1570)
	at org.apache.cloudstack.storage.allocator.AbstractStoragePoolAllocator.filter(AbstractStoragePoolAllocator.java:199)
	at org.apache.cloudstack.storage.allocator.ClusterScopeStoragePoolAllocator.select(ClusterScopeStoragePoolAllocator.java:110)
	at org.apache.cloudstack.storage.allocator.AbstractStoragePoolAllocator.allocateToPool(AbstractStoragePoolAllocator.java:109)
	at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.findStoragePool(VolumeOrchestrator.java:256)
	at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeFromSnapshot(VolumeOrchestrator.java:339)
	at com.cloud.storage.VolumeApiServiceImpl.createVolumeFromSnapshot(VolumeApiServiceImpl.java:785)
	at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:735)
	at com.cloud.storage.VolumeApiServiceImpl.createVolume(VolumeApiServiceImpl.java:177)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:622)
	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 com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:50)
	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 com.sun.proxy.$Proxy196.createVolume(Unknown Source)
	at org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd.execute(CreateVolumeCmd.java:196)
	at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:161)
	at com.cloud.api.ApiAsyncJobDispatcher.runJobInContext(ApiAsyncJobDispatcher.java:109)
	at com.cloud.api.ApiAsyncJobDispatcher$1.run(ApiAsyncJobDispatcher.java:66)
	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 com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:63)
	at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:509)
	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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:701)
2014-12-03 12:20:46,631 DEBUG [c.c.u.AccountManagerImpl] (Job-Executor-166: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-Executor-166:ctx-d915e890 ctx-d7a11540) Discrepency in the resource count (original count=107374182400 correct count = 85899345920) for type primary_storage 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-Executor-166:ctx-d915e890) Complete async job-2804, jobStatus: FAILED, resultCode: 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-Executor-166:ctx-d915e890) Done executing org.apache.cloudstack.api.command.user.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-3aa7826a) ===START===  111.client.ip.111 -- GET  command=queryAsyncJobResult&jobId=f943cc56-d7a8-4529-9990-1a3ee6e9a13d&response=json&sessionkey=CENSORED%3D&_=1417605821689
2014-12-03 12:20:49,689 DEBUG [c.c.a.ApiServlet] (http-6443-exec-95:ctx-3aa7826a ctx-d76a1f77) ===END===  111.client.ip.111 -- GET  command=queryAsyncJobResult&jobId=f943cc56-d7a8-4529-9990-1a3ee6e9a13d&response=json&sessionkey=CENSORED%3D&_=1417605821689
2014-12-03 12:20:50,015 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 27-839631: Processing Seq 27-839631:  { Cmd , MgmtId: -1, via: 27, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":473,"_loadInfo":"{\n  \"connections\": []\n}","wait":0}}] }
2014-12-03 12:20:50,144 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-12:null) SeqA 27-839631: Sending Seq 27-839631:  { Ans: , MgmtId: 95545481387, via: 27, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }


BTW there is a typo in the code, Discrepency should be DescrepAncy. 

Regards,
F.