[
https://issues.apache.org/jira/browse/CLOUDSTACK-7948?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14375733#comment-14375733
]
Rohit Yadav commented on CLOUDSTACK-7948:
-----------------------------------------
[~kishan] I think the patch is good so merging it. Let me know if any other
changes need to be done. The only issue I see is the assumption that VM
deletion will cause one event to be published, if in future this changes we
will have regressions.
> [Automation] Two "VOLUME.DELETE" Events are being registered instead of one -
> On Destroying a User VM belonging to a Project
> ----------------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-7948
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7948
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Automation, Test
> Affects Versions: 4.5.0
> Reporter: Chandan Purushothama
> Assignee: Kishan Kavala
> Fix For: 4.5.1
>
>
> ==========================================
> User VM in Project Events Information in the Database:
> ==========================================
> {noformat}
> mysql> select * from usage_event where account_id=6;
> +----+-------------------------+------------+---------------------+---------+-------------+----------------+-------------+-------------+-------------+----------------+-----------+--------------+
> | id | type | account_id | created | zone_id |
> resource_id | resource_name | offering_id | template_id | size |
> resource_type | processed | virtual_size |
> +----+-------------------------+------------+---------------------+---------+-------------+----------------+-------------+-------------+-------------+----------------+-----------+--------------+
> | 19 | TEMPLATE.CREATE | 6 | 2014-11-19 21:28:14 | 1 |
> 202 | TestTemplate-1 | NULL | NULL | 1708331520 | NULL
> | 0 | 8589934592 |
> | 20 | VOLUME.CREATE | 6 | 2014-11-19 21:32:23 | 1 |
> 9 | ROOT-9 | 1 | 5 | 21474836480 | NULL
> | 0 | NULL |
> | 21 | VM.CREATE | 6 | 2014-11-19 21:32:23 | 1 |
> 9 | Project-VM-1 | 1 | 5 | NULL |
> XenServer | 0 | NULL |
> | 22 | NET.IPASSIGN | 6 | 2014-11-19 21:32:25 | 1 |
> 6 | 10.219.196.151 | NULL | 0 | 0 |
> DirectAttached | 0 | NULL |
> | 23 | NETWORK.OFFERING.ASSIGN | 6 | 2014-11-19 21:32:33 | 1 |
> 9 | 19 | 6 | NULL | 1 | NULL
> | 0 | NULL |
> | 24 | SG.ASSIGN | 6 | 2014-11-19 21:32:33 | 1 |
> 9 | NULL | 4 | NULL | NULL | NULL
> | 0 | NULL |
> | 25 | VM.START | 6 | 2014-11-19 21:32:33 | 1 |
> 9 | Project-VM-1 | 1 | 5 | NULL |
> XenServer | 0 | NULL |
> | 26 | SG.REMOVE | 6 | 2014-11-19 21:33:10 | 1 |
> 9 | NULL | 4 | NULL | NULL | NULL
> | 0 | NULL |
> | 27 | VM.STOP | 6 | 2014-11-19 21:33:10 | 1 |
> 9 | Project-VM-1 | 1 | 5 | NULL |
> XenServer | 0 | NULL |
> | 28 | NETWORK.OFFERING.REMOVE | 6 | 2014-11-19 21:33:10 | 1 |
> 9 | 19 | 6 | NULL | 0 | NULL
> | 0 | NULL |
> | 31 | VM.DESTROY | 6 | 2014-11-20 00:08:37 | 1 |
> 9 | Project-VM-1 | 1 | 5 | NULL |
> XenServer | 0 | NULL |
> | 32 | VOLUME.DELETE | 6 | 2014-11-20 00:08:37 | 1 |
> 9 | ROOT-9 | NULL | NULL | NULL | NULL
> | 0 | NULL |
> | 33 | NET.IPRELEASE | 6 | 2014-11-20 00:08:39 | 1 |
> 6 | 10.219.196.151 | NULL | 0 | 0 |
> DirectAttached | 0 | NULL |
> | 34 | VOLUME.DELETE | 6 | 2014-11-20 00:08:39 | 1 |
> 9 | ROOT-9 | NULL | NULL | NULL | NULL
> | 0 | NULL |
> +----+-------------------------+------------+---------------------+---------+-------------+----------------+-------------+-------------+-------------+----------------+-----------+--------------+
> 14 rows in set (0.00 sec)
> {noformat}
> =================
> Destroy VM Job Log:
> =================
> {noformat}
> 2014-11-20 00:08:35,021 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (catalina-exec-11:ctx-fb3a3d80 ctx-67753d29) submit async job-50, details:
> AsyncJobVO {id:50, userId: 2, accountId: 2, instanceType: VirtualMachine,
> instanceId: 9, cmd:
> org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo:
> {"sessionkey":"KxWOb6uxo53LBRidu+yVRm8qK04\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","id":"ede32a62-67d7-487a-bb20-12c53d6e7c5a","response":"json","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"ede32a62-67d7-487a-bb20-12c53d6e7c5a\"}","projectid":"fa39cf9d-6d28-4673-8698-6781e59dbf6b","_":"1416442109090","expunge":"true","ctxAccountId":"2","uuid":"ede32a62-67d7-487a-bb20-12c53d6e7c5a","ctxStartEventId":"107"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 11627713415566, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: null}
> 2014-11-20 00:08:35,022 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (API-Job-Executor-13:ctx-70d3ae4d job-50) Add job-50 into job monitoring
> 2014-11-20 00:08:35,022 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50) Executing AsyncJobVO {id:50,
> userId: 2, accountId: 2, instanceType: VirtualMachine, instanceId: 9, cmd:
> org.apache.cloudstack.api.command.admin.vm.DestroyVMCmdByAdmin, cmdInfo:
> {"sessionkey":"KxWOb6uxo53LBRidu+yVRm8qK04\u003d","cmdEventType":"VM.DESTROY","ctxUserId":"2","httpmethod":"GET","id":"ede32a62-67d7-487a-bb20-12c53d6e7c5a","response":"json","ctxDetails":"{\"com.cloud.vm.VirtualMachine\":\"ede32a62-67d7-487a-bb20-12c53d6e7c5a\"}","projectid":"fa39cf9d-6d28-4673-8698-6781e59dbf6b","_":"1416442109090","expunge":"true","ctxAccountId":"2","uuid":"ede32a62-67d7-487a-bb20-12c53d6e7c5a","ctxStartEventId":"107"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 11627713415566, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: null}
> 2014-11-20 00:08:35,022 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-11:ctx-fb3a3d80 ctx-67753d29) ===END=== 10.252.113.187 -- GET
>
> command=destroyVirtualMachine&response=json&sessionkey=KxWOb6uxo53LBRidu%2ByVRm8qK04%3D&projectid=fa39cf9d-6d28-4673-8698-6781e59dbf6b&id=ede32a62-67d7-487a-bb20-12c53d6e7c5a&expunge=true&_=1416442109090
> 2014-11-20 00:08:35,032 WARN [c.c.a.d.ParamGenericValidationWorker]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Received unknown
> parameters for command destroyVirtualMachine. Unknown parameters : projectid
> 2014-11-20 00:08:35,053 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Destroying vm
> VM[User|i-6-9-CUSTOMERTEST]
> 2014-11-20 00:08:35,063 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Sync job-51 execution
> on object VmWorkJobQueue.9
> 2014-11-20 00:08:35,602 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-649609cc) Execute sync-queue item:
> SyncQueueItemVO {id:19, queueId: 17, contentType: AsyncJob, contentId: 51,
> lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null,
> created: Thu Nov 20 00:08:35 UTC 2014}
> 2014-11-20 00:08:35,603 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-649609cc) Schedule queued job-51
> 2014-11-20 00:08:35,607 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Add job-51 into job
> monitoring
> 2014-11-20 00:08:35,608 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Executing AsyncJobVO
> {id:51, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.vm.VmWorkStop, cmdInfo:
> rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 11627713415566, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Thu Nov 20 00:08:35 UTC 2014}
> 2014-11-20 00:08:35,609 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Run VM work job:
> com.cloud.vm.VmWorkStop for VM 9, job origin: 50
> 2014-11-20 00:08:35,610 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Execute VM
> work job:
> com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
> 2014-11-20 00:08:35,616 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) VM is already
> stopped: VM[User|i-6-9-CUSTOMERTEST]
> 2014-11-20 00:08:35,616 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Done executing
> VM work job:
> com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
> 2014-11-20 00:08:35,616 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Complete async
> job-51, jobStatus: SUCCEEDED, resultCode: 0, result: null
> 2014-11-20 00:08:35,618 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Publish async
> job-51 complete on message bus
> 2014-11-20 00:08:35,618 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Wake up jobs
> related to job-51
> 2014-11-20 00:08:35,618 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Update db
> status for job-51
> 2014-11-20 00:08:35,619 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51 ctx-2a95f6ae) Wake up jobs
> joined with job-51 and disjoin all subjobs created from job- 51
> 2014-11-20 00:08:35,624 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Done with run of VM work
> job: com.cloud.vm.VmWorkStop for VM 9, job origin: 50
> 2014-11-20 00:08:35,624 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Done executing
> com.cloud.vm.VmWorkStop for job-51
> 2014-11-20 00:08:35,627 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Sync queue (17) is
> currently empty
> 2014-11-20 00:08:35,628 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-14:ctx-eb594f01 job-50/job-51) Remove job-51 from job
> monitoring
> 2014-11-20 00:08:35,638 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Sync job-52 execution
> on object VmWorkJobQueue.9
> 2014-11-20 00:08:35,659 DEBUG [c.c.s.StatsCollector]
> (StatsCollector-2:ctx-4020448b) AutoScaling Monitor is running...
> 2014-11-20 00:08:37,601 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-908f32e6) Execute sync-queue item:
> SyncQueueItemVO {id:20, queueId: 17, contentType: AsyncJob, contentId: 52,
> lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null,
> created: Thu Nov 20 00:08:35 UTC 2014}
> 2014-11-20 00:08:37,603 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-908f32e6) Schedule queued job-52
> 2014-11-20 00:08:37,618 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Add job-52 into job
> monitoring
> 2014-11-20 00:08:37,618 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Executing AsyncJobVO
> {id:52, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots, cmdInfo:
> rO0ABXNyADBjb20uY2xvdWQudm0uc25hcHNob3QuVm1Xb3JrRGVsZXRlQWxsVk1TbmFwc2hvdHOsl-VRajf8cAIAAUwABHR5cGV0ACdMY29tL2Nsb3VkL3ZtL3NuYXBzaG90L1ZNU25hcHNob3QkVHlwZTt4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1ldAASTGphdmEvbGFuZy9TdHJpbmc7eHAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAAl0ABVWTVNuYXBzaG90TWFuYWdlckltcGxw,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 11627713415566, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Thu Nov 20 00:08:35 UTC 2014}
> 2014-11-20 00:08:37,618 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Run VM work job:
> com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots for VM 9, job origin: 50
> 2014-11-20 00:08:37,621 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Execute VM
> work job:
> com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots{"userId":2,"accountId":2,"vmId":9,"handlerName":"VMSnapshotManagerImpl"}
> 2014-11-20 00:08:37,630 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-ce4d53c8) Begin cleanup expired async-jobs
> 2014-11-20 00:08:37,637 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-ce4d53c8) End cleanup expired async-jobs
> 2014-11-20 00:08:37,661 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Done executing
> VM work job:
> com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots{"userId":2,"accountId":2,"vmId":9,"handlerName":"VMSnapshotManagerImpl"}
> 2014-11-20 00:08:37,661 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Complete async
> job-52, jobStatus: SUCCEEDED, resultCode: 0, result:
> rO0ABXNyABFqYXZhLmxhbmcuQm9vbGVhbs0gcoDVnPruAgABWgAFdmFsdWV4cAE
> 2014-11-20 00:08:37,663 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Publish async
> job-52 complete on message bus
> 2014-11-20 00:08:37,663 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Wake up jobs
> related to job-52
> 2014-11-20 00:08:37,663 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Update db
> status for job-52
> 2014-11-20 00:08:37,664 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52 ctx-8bca0dc3) Wake up jobs
> joined with job-52 and disjoin all subjobs created from job- 52
> 2014-11-20 00:08:37,679 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Done with run of VM work
> job: com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots for VM 9, job origin: 50
> 2014-11-20 00:08:37,680 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Done executing
> com.cloud.vm.snapshot.VmWorkDeleteAllVMSnapshots for job-52
> 2014-11-20 00:08:37,683 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Sync queue (17) is
> currently empty
> 2014-11-20 00:08:37,684 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-15:ctx-4d461fe6 job-50/job-52) Remove job-52 from job
> monitoring
> 2014-11-20 00:08:37,702 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) VM state transitted
> from :Stopped to Destroyed with event: DestroyRequestedvm's original host id:
> 1 new host id: null host id before state transition: null
> 2014-11-20 00:08:37,709 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Hosts's actual total
> CPU: 22400 and CPU after applying overprovisioning: 22400
> 2014-11-20 00:08:37,709 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Hosts's actual total
> RAM: 7434305920 and RAM after applying overprovisioning: 7434306048
> 2014-11-20 00:08:37,709 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) release cpu from host:
> 1, old used: 2000,reserved: 0, actual total: 22400, total with
> overprovisioning: 22400; new used: 2000,reserved:0; movedfromreserved:
> true,moveToReserveredfalse
> 2014-11-20 00:08:37,709 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) release mem from host:
> 1, old used: 2281701376,reserved: 0, total: 7434306048; new used:
> 2281701376,reserved:0; movedfromreserved: true,moveToReserveredfalse
> 2014-11-20 00:08:37,747 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Sync job-53 execution
> on object VmWorkJobQueue.9
> 2014-11-20 00:08:37,864 DEBUG [c.c.s.StatsCollector]
> (StatsCollector-4:ctx-f85ede2e) VmStatsCollector is running...
> 2014-11-20 00:08:37,878 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-378:ctx-72ebbb5a) Seq 1-6620572927211344033: Executing request
> 2014-11-20 00:08:37,901 DEBUG [c.c.h.x.r.CitrixResourceBase]
> (DirectAgent-378:ctx-72ebbb5a) Vm cpu utilization 0.10777777777777779
> 2014-11-20 00:08:37,901 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-378:ctx-72ebbb5a) Seq 1-6620572927211344033: Response Received:
> 2014-11-20 00:08:37,901 DEBUG [c.c.a.t.Request]
> (StatsCollector-4:ctx-f85ede2e) Seq 1-6620572927211344033: Received: { Ans:
> , MgmtId: 11627713415566, via: 1, Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2014-11-20 00:08:38,066 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-5:ctx-15a13cc5) ===START=== 10.252.113.187 -- GET
> command=queryAsyncJobResult&jobId=d0617b23-fc22-44ba-8d97-8e9b5c2889fb&response=json&sessionkey=KxWOb6uxo53LBRidu%2ByVRm8qK04%3D&projectid=fa39cf9d-6d28-4673-8698-6781e59dbf6b&_=1416442112364
> 2014-11-20 00:08:38,074 WARN [c.c.a.d.ParamGenericValidationWorker]
> (catalina-exec-5:ctx-15a13cc5 ctx-a8738fbc) Received unknown parameters for
> command queryAsyncJobResult. Unknown parameters : projectid
> 2014-11-20 00:08:38,086 DEBUG [c.c.a.ApiServlet]
> (catalina-exec-5:ctx-15a13cc5 ctx-a8738fbc) ===END=== 10.252.113.187 -- GET
> command=queryAsyncJobResult&jobId=d0617b23-fc22-44ba-8d97-8e9b5c2889fb&response=json&sessionkey=KxWOb6uxo53LBRidu%2ByVRm8qK04%3D&projectid=fa39cf9d-6d28-4673-8698-6781e59dbf6b&_=1416442112364
> 2014-11-20 00:08:38,845 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-4:null) SeqA 3-13515: Processing Seq 3-13515: { Cmd ,
> MgmtId: -1, via: 3, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
> \"connections\": []\n}","wait":0}}] }
> 2014-11-20 00:08:38,849 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-4:null) SeqA 3-13515: Sending Seq 3-13515: { Ans: ,
> MgmtId: 11627713415566, via: 3, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2014-11-20 00:08:39,602 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-d2cae0fb) Execute sync-queue item:
> SyncQueueItemVO {id:21, queueId: 17, contentType: AsyncJob, contentId: 53,
> lastProcessMsid: null, lastprocessNumber: null, lastProcessTime: null,
> created: Thu Nov 20 00:08:37 UTC 2014}
> 2014-11-20 00:08:39,604 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-d2cae0fb) Schedule queued job-53
> 2014-11-20 00:08:39,608 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Add job-53 into job
> monitoring
> 2014-11-20 00:08:39,608 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Executing AsyncJobVO
> {id:53, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd:
> com.cloud.vm.VmWorkStop, cmdInfo:
> rO0ABXNyABdjb20uY2xvdWQudm0uVm1Xb3JrU3RvcALQ4GymiWjjAgABWgAHY2xlYW51cHhyABNjb20uY2xvdWQudm0uVm1Xb3Jrn5m2VvAlZ2sCAARKAAlhY2NvdW50SWRKAAZ1c2VySWRKAAR2bUlkTAALaGFuZGxlck5hbWV0ABJMamF2YS9sYW5nL1N0cmluZzt4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAACXQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA,
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
> null, initMsid: 11627713415566, completeMsid: null, lastUpdated: null,
> lastPolled: null, created: Thu Nov 20 00:08:37 UTC 2014}
> 2014-11-20 00:08:39,610 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Run VM work job:
> com.cloud.vm.VmWorkStop for VM 9, job origin: 50
> 2014-11-20 00:08:39,611 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Execute VM
> work job:
> com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
> 2014-11-20 00:08:39,615 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Stopped called
> on VM[User|i-6-9-CUSTOMERTEST] but the state is Destroyed
> 2014-11-20 00:08:39,615 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Done executing
> VM work job:
> com.cloud.vm.VmWorkStop{"cleanup":false,"userId":2,"accountId":2,"vmId":9,"handlerName":"VirtualMachineManagerImpl"}
> 2014-11-20 00:08:39,615 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Complete async
> job-53, jobStatus: SUCCEEDED, resultCode: 0, result: null
> 2014-11-20 00:08:39,617 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Publish async
> job-53 complete on message bus
> 2014-11-20 00:08:39,617 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Wake up jobs
> related to job-53
> 2014-11-20 00:08:39,617 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Update db
> status for job-53
> 2014-11-20 00:08:39,618 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53 ctx-c1bf9be1) Wake up jobs
> joined with job-53 and disjoin all subjobs created from job- 53
> 2014-11-20 00:08:39,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Done with run of VM work
> job: com.cloud.vm.VmWorkStop for VM 9, job origin: 50
> 2014-11-20 00:08:39,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Done executing
> com.cloud.vm.VmWorkStop for job-53
> 2014-11-20 00:08:39,639 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Sync queue (17) is
> currently empty
> 2014-11-20 00:08:39,641 INFO [o.a.c.f.j.i.AsyncJobMonitor]
> (Work-Job-Executor-16:ctx-dd0514f7 job-50/job-53) Remove job-53 from job
> monitoring
> 2014-11-20 00:08:39,645 DEBUG [c.c.c.CapacityManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) VM state transitted
> from :Destroyed to Expunging with event: ExpungeOperationvm's original host
> id: 1 new host id: null host id before state transition: null
> 2014-11-20 00:08:39,645 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Destroying vm
> VM[User|i-6-9-CUSTOMERTEST]
> 2014-11-20 00:08:39,645 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Cleaning up NICS
> 2014-11-20 00:08:39,645 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Cleaning network for
> vm: 9
> 2014-11-20 00:08:39,659 DEBUG [c.c.n.g.DirectNetworkGuru]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Deallocate network:
> networkId: 204, ip: 10.219.196.151
> 2014-11-20 00:08:39,699 DEBUG [c.c.n.g.DirectNetworkGuru]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) remove nic 19
> secondary ip
> 2014-11-20 00:08:39,704 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Removed nic id=19
> 2014-11-20 00:08:39,705 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Revoving nic secondary
> ip entry ...
> 2014-11-20 00:08:39,706 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Cleaning up hypervisor
> data structures (ex. SRs in XenServer) for managed storage
> 2014-11-20 00:08:39,715 DEBUG [o.a.c.e.o.VolumeOrchestrator]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Cleaning storage for
> vm: 9
> 2014-11-20 00:08:39,754 DEBUG [c.c.a.t.Request]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Seq
> 1-6620572927211344034: Sending { Cmd , MgmtId: 11627713415566, via: 1(bear),
> Ver: v1, Flags: 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"165eb875-341d-4d75-be5e-9dcc2e10a779","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fe44f477-1a11-317e-be90-8add5f52fbd9","id":1,"poolType":"NetworkFilesystem","host":"10.219.192.40","path":"/vol/exports/901529-XrA7qT","port":2049,"url":"NetworkFilesystem://10.219.192.40/vol/exports/901529-XrA7qT/?ROLE=Primary&STOREUUID=fe44f477-1a11-317e-be90-8add5f52fbd9"}},"name":"ROOT-9","size":21474836480,"path":"017150f6-f7fd-4e50-9bb6-d853b0577e61","volumeId":9,"vmName":"i-6-9-CUSTOMERTEST","accountId":6,"format":"VHD","provisioningType":"THIN","id":9,"deviceId":0,"hypervisorType":"XenServer"}},"wait":0}}]
> }
> 2014-11-20 00:08:39,755 DEBUG [c.c.a.t.Request]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Seq
> 1-6620572927211344034: Executing: { Cmd , MgmtId: 11627713415566, via:
> 1(bear), Ver: v1, Flags: 100011,
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"165eb875-341d-4d75-be5e-9dcc2e10a779","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"fe44f477-1a11-317e-be90-8add5f52fbd9","id":1,"poolType":"NetworkFilesystem","host":"10.219.192.40","path":"/vol/exports/901529-XrA7qT","port":2049,"url":"NetworkFilesystem://10.219.192.40/vol/exports/901529-XrA7qT/?ROLE=Primary&STOREUUID=fe44f477-1a11-317e-be90-8add5f52fbd9"}},"name":"ROOT-9","size":21474836480,"path":"017150f6-f7fd-4e50-9bb6-d853b0577e61","volumeId":9,"vmName":"i-6-9-CUSTOMERTEST","accountId":6,"format":"VHD","provisioningType":"THIN","id":9,"deviceId":0,"hypervisorType":"XenServer"}},"wait":0}}]
> }
> 2014-11-20 00:08:39,755 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-95:ctx-1785c8ca) Seq 1-6620572927211344034: Executing request
> 2014-11-20 00:08:39,945 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-95:ctx-1785c8ca) Seq 1-6620572927211344034: Response Received:
> 2014-11-20 00:08:39,946 DEBUG [c.c.a.t.Request] (DirectAgent-95:ctx-1785c8ca)
> Seq 1-6620572927211344034: Processing: { Ans: , MgmtId: 11627713415566, via:
> 1, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":true,"wait":0}}] }
> 2014-11-20 00:08:39,946 DEBUG [c.c.a.t.Request]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Seq
> 1-6620572927211344034: Received: { Ans: , MgmtId: 11627713415566, via: 1,
> Ver: v1, Flags: 10, { Answer } }
> 2014-11-20 00:08:39,955 INFO [o.a.c.s.v.VolumeServiceImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Volume 9 is not
> referred anywhere, remove it from volumes table
> 2014-11-20 00:08:39,977 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Expunged
> VM[User|i-6-9-CUSTOMERTEST]
> 2014-11-20 00:08:39,984 DEBUG [c.c.u.AccountManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Access granted to
> Acct[dde8b620-6f53-11e4-9960-0a9349ba498e-admin] to Domain:1/ by
> AffinityGroupAccessChecker
> 2014-11-20 00:08:39,993 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Starting cleaning up
> vm VM[User|i-6-9-CUSTOMERTEST] resources...
> 2014-11-20 00:08:40,013 INFO [c.c.n.s.SecurityGroupManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Disassociated 1
> network groups from uservm 9
> 2014-11-20 00:08:40,015 DEBUG [c.c.n.s.SecurityGroupManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Security group
> mappings are removed successfully for vm id=9
> 2014-11-20 00:08:40,033 DEBUG [c.c.n.f.FirewallManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) No firewall rules are
> found for vm id=9
> 2014-11-20 00:08:40,039 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Firewall rules are
> removed successfully as a part of vm id=9 expunge
> 2014-11-20 00:08:40,043 DEBUG [c.c.n.r.RulesManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) No port forwarding
> rules are found for vm id=9
> 2014-11-20 00:08:40,043 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Port forwarding rules
> are removed successfully as a part of vm id=9 expunge
> 2014-11-20 00:08:40,063 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Removed vm id=9 from
> all load balancers as a part of expunge process
> 2014-11-20 00:08:40,065 DEBUG [c.c.v.UserVmManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Successfully cleaned
> up vm VM[User|i-6-9-CUSTOMERTEST] resources as a part of expunge process
> 2014-11-20 00:08:40,084 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-13:ctx-70d3ae4d job-50 ctx-012a756f) Complete async job-50,
> jobStatus: SUCCEEDED, resultCode: 0, result:
> org.apache.cloudstack.api.response.UserVmResponse/null/{"securitygroup":[],"nic":[],"tags":[],"affinitygroup":[]}
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
