[
https://issues.apache.org/jira/browse/CLOUDSTACK-5005?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13811105#comment-13811105
]
Pavan Kumar Bandarupally commented on CLOUDSTACK-5005:
------------------------------------------------------
I have seen this issue even when it is not a parallel VM deployment. Here are
job traces:
--------------------------------------------------------------
2013-11-01 18:12:35,690 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-3:null) submit async job-41 = [
bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ], details: AsyncJobVO {id:41, userId: 2,
accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 3,
cmd: org.apache.cloudstack.api.command.user.vm.StopVMCmd, cmdOriginator: null,
cmdInfo:
{"id":"f69ea75b-b3cd-4f74-8810-866bd0d557d5","response":"json","sessionkey":"VXAURlAF7J9QjdwOd2+hXFtYzQQ\u003d","cmdEventType":"VM.STOP","ctxUserId":"2","httpmethod":"GET","_":"1383290487063","ctxAccountId":"2","ctxStartEventId":"151","forced":"false"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 6804838809635,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-11-01 18:12:35,694 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Executing
org.apache.cloudstack.api.command.user.vm.StopVMCmd for job-41 = [
bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]
2013-11-01 18:12:35,701 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) ControlledEntity name
is:com.cloud.vm.VirtualMachine
2013-11-01 18:12:35,703 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) ControlledEntity name
is:com.cloud.uservm.UserVm
2013-11-01 18:12:35,704 DEBUG [cloud.api.ApiDispatcher] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) ControlledEntity name
is:com.cloud.network.router.VirtualRouter
2013-11-01 18:12:35,736 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) VM state
transitted from :Running to Stopping with event: StopRequestedvm's original
host id: 1 new host id: 1 host id before state transition: 1
2013-11-01 18:12:35,740 DEBUG [agent.transport.Request] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Seq 1-1827016164: Sending { Cmd ,
MgmtId: 6804838809635, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-3-VM","wait":0}}]
}
2013-11-01 18:12:35,740 DEBUG [agent.transport.Request] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Seq 1-1827016164: Executing: { Cmd
, MgmtId: 6804838809635, via: 1, Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"vmName":"i-2-3-VM","wait":0}}]
}
2013-11-01 18:12:59,595 DEBUG [agent.transport.Request] (Job-Executor-19:job-41
= [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Seq 1-1827016164: Received: { Ans:
, MgmtId: 6804838809635, via: 1, Ver: v1, Flags: 110, { StopAnswer } }
2013-11-01 18:12:59,671 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ])
VM[User|w2k8R2NoPV] is stopped on the host. Proceeding to release resource
held.
2013-11-01 18:12:59,687 DEBUG [db.Transaction.Transaction]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Rolling
back the transaction: Time = 9 Name =
-AsyncJobManagerImpl$1.run:494-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679;
called by
-Transaction.rollback:897-Transaction.removeUpTo:840-Transaction.close:664-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:2394-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.advanceStop:1324-VirtualMachineManagerImpl.stop:1053-VMEntityManagerImpl.stopvirtualmachine:251-VirtualMachineEntityImpl.stop:214-UserVmManagerImpl.stopVirtualMachine:3255
2013-11-01 18:12:59,691 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ])
Successfully released network resources for the vm VM[User|w2k8R2NoPV]
2013-11-01 18:12:59,691 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ])
Successfully released storage resources for the vm VM[User|w2k8R2NoPV]
2013-11-01 18:12:59,705 DEBUG [vm.dao.VMInstanceDaoImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Unable to
update VM[User|w2k8R2NoPV]: DB Data={Host=null; State=Stopped; updated=15;
time=Fri Nov 01 18:12:59 IST 2013} New Data: {Host=null; State=Stopped;
updated=15; time=Fri Nov 01 18:12:59 IST 2013} Stale Data: {Host=1;
State=Stopping; updated=14; time=Fri Nov 01 18:12:35 IST 2013}
2013-11-01 18:12:59,726 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-19:job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]) Complete
async job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ], jobStatus: 2,
resultCode: 530, result: Error Code: 530 Error text: Failed to stop vm
2013-11-01 18:12:59,768 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-7:null) Async job-41 = [ bd013e4f-d898-4c97-9c77-b2ead3dbfd6c ]
completed
---------------------------------------------------------------
> issue with stopping vms parallelly
> -----------------------------------
>
> Key: CLOUDSTACK-5005
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5005
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Affects Versions: 4.2.1
> Reporter: prashant kumar mishra
> Assignee: Sheng Yang
> Attachments: MS_XEN_DB.rar
>
>
> steps to reproduce
> ---------------------------
> 1-prepare CS setup with xen 6.1
> 2-set execute.in.sequence.hypervisor.commands and
> execute.in.sequence.network.element.commands to false
> 3-Restart MS
> 4-deploy 35 vms parallelly with default centOS template
> 5-try to stop all uservms using script
> Expected
> -------------
> All vms should get stopped ,
> Actual
> ------------
> before vms went in stopped state , Log show error messages
> Logs
> --------
> [root@localhost ~]# grep "job-436"
> /var/log/cloudstack/management/management-server.log
> 2013-10-30 12:21:57,817 DEBUG [cloud.async.AsyncJobManagerImpl]
> (ApiServer-1:null) submit async job-436 = [
> 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ], details: AsyncJobVO {id:436, userId:
> 1, accountId: 1, sessionKey: null, instanceType: VirtualMachine, instanceId:
> 78, cmd: org.apache.cloudstack.api.command.user.vm.StopVMCmd, cmdOriginator:
> null, cmdInfo:
> {"id":"78","cmdEventType":"VM.STOP","ctxUserId":"1","httpmethod":"GET","ctxAccountId":"1","ctxStartEventId":"1384"},
> cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
> processStatus: 0, resultCode: 0, result: null, initMsid: 7484181839895,
> completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
> 2013-10-30 12:21:57,818 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> Executing org.apache.cloudstack.api.command.user.vm.StopVMCmd for job-436 = [
> 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]
> 2013-10-30 12:21:57,941 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> ControlledEntity name is:com.cloud.vm.VirtualMachine
> 2013-10-30 12:21:58,056 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> ControlledEntity name is:com.cloud.uservm.UserVm
> 2013-10-30 12:21:58,111 DEBUG [cloud.api.ApiDispatcher]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> ControlledEntity name is:com.cloud.network.router.VirtualRouter
> 2013-10-30 12:21:58,528 DEBUG [cloud.capacity.CapacityManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) VM
> state transitted from :Running to Stopping with event: StopRequestedvm's
> original host id: 3 new host id: 3 host id before state transition: 3
> 2013-10-30 12:21:58,696 DEBUG [agent.transport.Request]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Seq
> 3-125568146: Sending { Cmd , MgmtId: 7484181839895, via: 3, Ver: v1, Flags:
> 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-78-VM","wait":0}}]
> }
> 2013-10-30 12:21:58,696 DEBUG [agent.transport.Request]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Seq
> 3-125568146: Executing: { Cmd , MgmtId: 7484181839895, via: 3, Ver: v1,
> Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"i-2-78-VM","wait":0}}]
> }
> 2013-10-30 12:22:58,051 DEBUG [agent.transport.Request]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Seq
> 3-125568146: Received: { Ans: , MgmtId: 7484181839895, via: 3, Ver: v1,
> Flags: 10, { StopAnswer } }
> 2013-10-30 12:22:58,078 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> VM[User|f1ad8bfe-b9a4-4669-a37c-f0edb2f0098f] is stopped on the host.
> Proceeding to release resource held.
> 2013-10-30 12:22:58,088 DEBUG [cloud.network.NetworkModelImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Service
> SecurityGroup is not supported in the network id=204
> 2013-10-30 12:22:58,095 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> Changing active number of nics for network id=204 on -1
> 2013-10-30 12:22:58,123 DEBUG [cloud.network.NetworkManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Asking
> VirtualRouter to release
> Nic[89-78-d1a70d9b-1e6e-4de8-bd4b-6f0649faf997-10.1.1.177]
> 2013-10-30 12:22:58,123 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> Successfully released network resources for the vm
> VM[User|f1ad8bfe-b9a4-4669-a37c-f0edb2f0098f]
> 2013-10-30 12:22:58,123 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> Successfully released storage resources for the vm
> VM[User|f1ad8bfe-b9a4-4669-a37c-f0edb2f0098f]
> 2013-10-30 12:22:58,141 DEBUG [vm.dao.VMInstanceDaoImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ]) Unable
> to update VM[User|f1ad8bfe-b9a4-4669-a37c-f0edb2f0098f]: DB Data={Host=3;
> State=Running; updated=5; time=Wed Oct 30 12:22:58 EDT 2013} New Data:
> {Host=null; State=Stopped; updated=5; time=Wed Oct 30 12:22:58 EDT 2013}
> Stale Data: {Host=3; State=Stopping; updated=4; time=Wed Oct 30 12:21:58 EDT
> 2013}
> 2013-10-30 12:22:58,161 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-122:job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ])
> Complete async job-436 = [ 432f8bd7-8f4b-4e72-b69b-b148fc1733dc ], jobStatus:
> 2, resultCode: 530, result: Error Code: 530 Error text: Failed to stop vm
> Log2
> -------
> 2013-10-30 12:25:54,535 INFO [xen.resource.XenServer56Resource]
> (DirectAgent-262:null) Catch com.xensource.xenapi.Types$VifInUse: failed to
> destory VLAN eth0 on host 7f8a4f8f-1c15-4b7a-95cf-1f64b09ce674 due to Network
> has active VIFs
--
This message was sent by Atlassian JIRA
(v6.1#6144)
