Chandan Purushothama created CLOUDSTACK-7604:
------------------------------------------------
Summary: [Automation] NPE during deletion of Volume
Key: CLOUDSTACK-7604
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7604
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Automation, Test, Volumes
Affects Versions: 4.5.0
Reporter: Chandan Purushothama
Priority: Critical
Fix For: 4.5.0
*Null Pointer Exception:*
{noformat}
2014-09-21 16:19:44,090 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Removed vm id=325 from
all load balancers as a part of expunge process
2014-09-21 16:19:44,091 DEBUG [c.c.v.UserVmManagerImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Successfully cleaned
up vm VM[User|i-163-325-VM] resources as a part of expunge process
2014-09-21 16:19:44,098 INFO [c.c.s.VolumeApiServiceImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Expunging volume 362
from primary data store
2014-09-21 16:19:44,116 DEBUG [c.c.a.t.Request]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Seq
1-5202783469519768584: Sending { Cmd , MgmtId: 16226561876200, via:
1(xrtuk-02-05), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"53c820f0-13f4-4fcf-8bf5-ccb2967453a5","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3161f583-6550-363c-9d0b-44aede011126","id":1,"poolType":"NetworkFilesystem","host":"10.81.24.13","path":"/vol/xenrtnfs/836249-z1NhU1","port":2049,"url":"NetworkFilesystem://10.81.24.13/vol/xenrtnfs/836249-z1NhU1/?ROLE=Primary&STOREUUID=3161f583-6550-363c-9d0b-44aede011126"}},"name":"ROOT-320","size":5368709120,"path":"827d2dae-4b86-4e75-a298-084d70553395","volumeId":362,"accountId":163,"format":"VHD","provisioningType":"THIN","id":362,"hypervisorType":"XenServer"}},"wait":0}}]
}
2014-09-21 16:19:44,117 DEBUG [c.c.a.t.Request]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Seq
1-5202783469519768584: Executing: { Cmd , MgmtId: 16226561876200, via:
1(xrtuk-02-05), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"53c820f0-13f4-4fcf-8bf5-ccb2967453a5","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"3161f583-6550-363c-9d0b-44aede011126","id":1,"poolType":"NetworkFilesystem","host":"10.81.24.13","path":"/vol/xenrtnfs/836249-z1NhU1","port":2049,"url":"NetworkFilesystem://10.81.24.13/vol/xenrtnfs/836249-z1NhU1/?ROLE=Primary&STOREUUID=3161f583-6550-363c-9d0b-44aede011126"}},"name":"ROOT-320","size":5368709120,"path":"827d2dae-4b86-4e75-a298-084d70553395","volumeId":362,"accountId":163,"format":"VHD","provisioningType":"THIN","id":362,"hypervisorType":"XenServer"}},"wait":0}}]
}
2014-09-21 16:19:44,117 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-273:ctx-25b5c023) Seq 1-5202783469519768584: Executing request
2014-09-21 16:19:44,236 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-2837c726)
===START=== 10.81.29.29 -- GET
jobid=908d3367-c7db-4bdd-90d6-ebaff799ecd3&apiKey=mLrTCdYRf3-d4xO7DnO-QXw1Uqrdae1uxenHTEPj_ulDpIYTaujsXwkNzARz222s6M4xChsTAE2W-TUur5bKNQ&command=queryAsyncJobResult&response=json&signature=TgBQLMCJxcuRj%2BNOZFHatiLZSzw%3D
2014-09-21 16:19:44,253 DEBUG [c.c.a.ApiServlet] (catalina-exec-7:ctx-2837c726
ctx-8f7c1e09 ctx-c08f5999) ===END=== 10.81.29.29 -- GET
jobid=908d3367-c7db-4bdd-90d6-ebaff799ecd3&apiKey=mLrTCdYRf3-d4xO7DnO-QXw1Uqrdae1uxenHTEPj_ulDpIYTaujsXwkNzARz222s6M4xChsTAE2W-TUur5bKNQ&command=queryAsyncJobResult&response=json&signature=TgBQLMCJxcuRj%2BNOZFHatiLZSzw%3D
2014-09-21 16:19:44,517 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-273:ctx-25b5c023) Seq 1-5202783469519768584: Response Received:
2014-09-21 16:19:44,517 DEBUG [c.c.a.t.Request] (DirectAgent-273:ctx-25b5c023)
Seq 1-5202783469519768584: Processing: { Ans: , MgmtId: 16226561876200, via:
1, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
2014-09-21 16:19:44,517 DEBUG [c.c.a.t.Request]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Seq
1-5202783469519768584: Received: { Ans: , MgmtId: 16226561876200, via: 1, Ver:
v1, Flags: 10, { Answer } }
2014-09-21 16:19:44,524 INFO [o.a.c.s.v.VolumeServiceImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) Volume 362 is not
referred anywhere, remove it from volumes table
2014-09-21 16:19:44,534 DEBUG [c.c.h.x.r.XenServerStorageProcessor]
(DirectAgent-488:ctx-5364176a) Failed to delete volume
You gave an invalid object reference. The object may have recently been
deleted. The class parameter gives the type of reference given, and the handle
parameter echoes the bad value given.
at com.xensource.xenapi.Types.checkResponse(Types.java:693)
at com.xensource.xenapi.Connection.dispatch(Connection.java:395)
at
com.cloud.hypervisor.xenserver.resource.XenServerConnectionPool$XenServerConnection.dispatch(XenServerConnectionPool.java:463)
at com.xensource.xenapi.VDI.destroy(VDI.java:416)
at
com.cloud.hypervisor.xenserver.resource.XenServerStorageProcessor.deleteVDI(XenServerStorageProcessor.java:439)
at
com.cloud.hypervisor.xenserver.resource.XenServerStorageProcessor.deleteVolume(XenServerStorageProcessor.java:503)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:124)
at
com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:57)
at
com.cloud.hypervisor.xenserver.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:530)
at
com.cloud.hypervisor.xenserver.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:64)
at
com.cloud.hypervisor.xenserver.resource.XenServer610Resource.executeRequest(XenServer610Resource.java:87)
at
com.cloud.hypervisor.xenserver.resource.XenServer620SP1Resource.executeRequest(XenServer620SP1Resource.java:65)
at
com.cloud.agent.manager.DirectAgentAttache$Task.runInContext(DirectAgentAttache.java:302)
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-09-21 16:19:44,539 INFO [c.c.u.AccountManagerImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) deleteAccount: Deleted
1 network groups for account 163
2014-09-21 16:19:44,542 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-488:ctx-5364176a) Seq 2-5748563449361730931: Response Received:
2014-09-21 16:19:44,543 DEBUG [c.c.a.t.Request] (DirectAgent-488:ctx-5364176a)
Seq 2-5748563449361730931: Processing: { Ans: , MgmtId: 16226561876200, via:
2, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":false,"details":"You gave an invalid
object reference. The object may have recently been deleted. The class
parameter gives the type of reference given, and the handle parameter echoes
the bad value given.","wait":0}}] }
2014-09-21 16:19:44,543 DEBUG [c.c.a.t.Request]
(StorageManager-Scavenger-2:ctx-ac357425) Seq 2-5748563449361730931: Received:
{ Ans: , MgmtId: 16226561876200, via: 2, Ver: v1, Flags: 10, { Answer } }
2014-09-21 16:19:44,543 DEBUG [o.a.c.s.v.VolumeObject]
(StorageManager-Scavenger-2:ctx-ac357425) Failed to update state
java.lang.NullPointerException
at com.cloud.utils.fsm.StateMachine2.transitTo(StateMachine2.java:101)
at
org.apache.cloudstack.storage.volume.VolumeObject.stateTransit(VolumeObject.java:185)
at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:325)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.deleteVolumeCallback(VolumeServiceImpl.java:339)
at sun.reflect.GeneratedMethodAccessor408.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:25)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:126)
at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.deleteAsync(CloudStackPrimaryDataStoreDriverImpl.java:222)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:323)
at
com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1058)
at
com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1280)
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.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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-09-21 16:19:44,544 DEBUG [o.a.c.s.v.VolumeServiceImpl]
(StorageManager-Scavenger-2:ctx-ac357425) ignore delete volume status update
failure, it will be picked up by storage clean up thread later
java.lang.NullPointerException
at
org.apache.cloudstack.storage.volume.VolumeObject.processEvent(VolumeObject.java:331)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.deleteVolumeCallback(VolumeServiceImpl.java:339)
at sun.reflect.GeneratedMethodAccessor408.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.dispatch(AsyncCallbackDispatcher.java:148)
at
org.apache.cloudstack.framework.async.InplaceAsyncCallbackDriver.performCompletionCallback(InplaceAsyncCallbackDriver.java:25)
at
org.apache.cloudstack.framework.async.AsyncCallbackDispatcher.complete(AsyncCallbackDispatcher.java:126)
at
org.apache.cloudstack.storage.datastore.driver.CloudStackPrimaryDataStoreDriverImpl.deleteAsync(CloudStackPrimaryDataStoreDriverImpl.java:222)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.expungeVolumeAsync(VolumeServiceImpl.java:323)
at
com.cloud.storage.StorageManagerImpl.cleanupStorage(StorageManagerImpl.java:1058)
at
com.cloud.storage.StorageManagerImpl$StorageGarbageCollector.runInContext(StorageManagerImpl.java:1280)
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.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
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-09-21 16:19:44,545 INFO [c.c.u.AccountManagerImpl]
(API-Job-Executor-16:ctx-3978d571 job-3320 ctx-d788d20d) deleteAccount: Deleted
0 affinity groups for account 163
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
