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.
