prashant kumar mishra created CLOUDSTACK-5005:
-------------------------------------------------
Summary: 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
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
[root@localhost ~]# vim /var/log/cloudstack/management/management-server.log
[root@localhost ~]# vim /var/log/cloudstack/management/management-server.log
[root@localhost ~]# vim /var/log/cloudstack/management/management-server.log
[root@localhost ~]# vi /var/log/cloudstack/management/management-server.log
[root@localhost ~]# vi /var/log/cloudstack/management/management-server.log
[root@localhost ~]# vi /var/log/cloudstack/management/management-server.log
[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)
