<!--
Verify first that your issue/request is not already reported on GitHub.
Also test if the latest release and master branch are affected too.
Always add information AFTER of these HTML comments, but no need to delete the
comments.
-->
##### ISSUE TYPE
<!-- Pick one below and delete the rest -->
* Bug Report
##### COMPONENT NAME
<!--
Categorize the issue, e.g. API, VR, VPN, UI, etc.
-->
~~~
VM
~~~
##### CLOUDSTACK VERSION
<!--
New line separated list of affected versions, commit ID for issues on master
branch.
-->
~~~
4.11.1
~~~
##### CONFIGURATION
<!--
Information about the configuration if relevant, e.g. basic network, advanced
networking, etc. N/A otherwise
-->
##### OS / ENVIRONMENT
<!--
Information about the environment if relevant, N/A otherwise
-->
VMware 5.5
##### SUMMARY
<!-- Explain the problem/feature briefly -->
Upgraded ACS from 4.5.x to 4.11.1. Some existing VMs which we could stop/start
under 4.5 can no longer be started with cloudstack after stopping. After
rollback to 4.5, the VM can be started again with cloudstack. The VM is quite
"old", created 01 Apr 2015 09:09:40. The VM _can_ be started on vCenter also
also stopped by cloudstack, but not started with cloudstack.
Another newer VM (2018), but created also before the upgrade 4.11.1, can be
stopped and started with cloudstack. So it is not a general problem.
We didn't find the reason why this particular VM can not be started.
##### STEPS TO REPRODUCE
<!--
For bugs, show exactly how to reproduce the problem, using a minimal test-case.
Use Screenshots if accurate.
For new features, show how the feature would be used.
-->
<!-- Paste example playbooks or commands between quotes below -->
~~~
?
~~~
<!-- You can also paste gist.github.com links for larger files -->
##### EXPECTED RESULTS
<!-- What did you expect to happen when running the steps above? -->
~~~
VM is started
~~~
##### ACTUAL RESULTS
<!-- What actually happened? -->
<!-- Paste verbatim command output between quotes below -->
~~~
[root@ma-cloud management]# tail -n 1000000 -f management-server.log | grep
ctx-749d330b
2018-09-07 14:18:35,880 DEBUG [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Execute VM
work job:
com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"userId":2,"accountId":2,"vmId":172,"handlerName":"VirtualMachineManagerImpl"}
2018-09-07 14:18:35,899 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Stopped to Starting with event: StartRequestedvm's original
host id: 1 new host id: null host id before state transition: null
2018-09-07 14:18:35,900 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully transitioned to start state for VM[User|i-28-172-VM] reservation
id = f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf
2018-09-07 14:18:35,902 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1,
hostId: 1, poolId: null
2018-09-07 14:18:35,902 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Deploy
avoids pods: null, clusters: null, hosts: null
2018-09-07 14:18:35,906 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Root
volume is ready, need to place VM in volume's cluster
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
DeploymentPlanner allocation algorithm: null
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
1800, requested ram: 1073741824
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Is ROOT
volume READY (pool already allocated)?: Yes
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
DeploymentPlan has host_id specified, choosing this host and making no checks
on this host: 1
2018-09-07 14:18:35,916 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Looking
for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2018-09-07 14:18:35,919 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Checking
suitable pools for volume (Id, Type): (183,ROOT)
2018-09-07 14:18:35,919 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Volume has
pool already allocated, checking if pool can be reused, poolId: 2
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Planner
need not allocate a pool for this volume since its READY
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Trying to
find a potenial host and associated storage pools from the suitable host/pool
lists for this VM
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Checking
if host: 1 can access any suitable storage pool for volume: ROOT
2018-09-07 14:18:35,922 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Host: 1
can access pool: 2
2018-09-07 14:18:35,923 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Found a
potential host id: 1 name: ix-mapod01-esx02.stxt.media.int and associated
storage pools for this VM
2018-09-07 14:18:35,924 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Returning
Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2018-09-07 14:18:35,924 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Deployment
found - P0=VM[User|i-28-172-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2018-09-07 14:18:35,955 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Starting to Starting with event: OperationRetryvm's original
host id: 1 new host id: 1 host id before state transition: null
2018-09-07 14:18:35,955 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM
starting again on the last host it was stopped on
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total CPU: 45600 and CPU after applying overprovisioning: 912000
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) We are
allocating VM, increasing the used capacity of this host:1
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Current
Used CPU: 0 , Free CPU:912000 ,Requested CPU: 1800
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Current
Used RAM: 0 , Free RAM:4121704792064 ,Requested RAM: 1073741824
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) We are
allocating VM to the last host again, so adjusting the reserved capacity if it
is not less than required
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Reserved
CPU: 0 , Requested CPU: 1800
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Reserved
RAM: 0 , Requested RAM: 1073741824
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) CPU STATS
after allocation: for host: 1, old used: 0, old reserved: 0, actual total:
45600, total with overprovisioning: 912000; new used:1800, reserved:0;
requested cpu:1800,alloc_from_last:true
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) RAM STATS
after allocation: for host: 1, old used: 0, old reserved: 0, total:
4121704792064; new used: 1073741824, reserved: 0; requested mem:
1073741824,alloc_from_last:true
2018-09-07 14:18:35,971 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Network
id=224 is already implemented
2018-09-07 14:18:35,984 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:35,988 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Changing
active number of nics for network id=224 on 1
2018-09-07 14:18:35,997 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Asking
VirtualRouter to prepare for
Nic[293-172-f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf-10.1.1.39]
2018-09-07 14:18:36,013 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:36,016 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) CONFIG
DHCP FOR SUBNETS RULES
2018-09-07 14:18:36,027 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:36,030 DEBUG [network.topology.AdvancedNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) APPLYING
VPC DHCP ENTRY RULES
2018-09-07 14:18:36,030 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Applying
dhcp entry in network Ntwk[224|Guest|8]
2018-09-07 14:18:36,048 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Sending { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:68:f0:00:01","vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:68:f0:00:01","isDefault":true,"executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:18:36,048 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Executing: { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:68:f0:00:01","vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:68:f0:00:01","isDefault":true,"executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:01,464 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Received: { Ans: , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 110, { GroupAnswer } }
2018-09-07 14:19:01,472 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:01,475 DEBUG [network.topology.AdvancedNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) APPLYING
VPC USERDATA RULES
2018-09-07 14:19:01,475 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Applying
userdata and password entry in network Ntwk[224|Guest|8]
2018-09-07 14:19:01,485 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Sending { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:01,486 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Executing: { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:26,429 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Received: { Ans: , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 110, { GroupAnswer } }
2018-09-07 14:19:26,430 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:26,435 DEBUG [engine.orchestration.VolumeOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) No need to
recreate the volume: Vol[183|vm=172|ROOT], since it already has a pool
assigned: 2, adding disk to VM
2018-09-07 14:19:26,452 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Cleaning
up resources for the vm VM[User|i-28-172-VM] in Starting state
2018-09-07 14:19:26,457 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Sending { Cmd , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-28-172-VM","executeInSequence":false,"wait":0}}]
}
2018-09-07 14:19:26,457 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Executing: { Cmd , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-28-172-VM","executeInSequence":false,"wait":0}}]
}
2018-09-07 14:19:26,692 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Received: { Ans: , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 10, { StopAnswer } }
2018-09-07 14:19:26,701 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:26,704 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Changing
active number of nics for network id=224 on -1
2018-09-07 14:19:26,713 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Asking
VirtualRouter to release
NicProfile[293-172-f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf-10.1.1.39-null
2018-09-07 14:19:26,713 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully released network resources for the vm VM[User|i-28-172-VM]
2018-09-07 14:19:26,713 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully cleanued up resources for the vm VM[User|i-28-172-VM] in Starting
state
2018-09-07 14:19:26,724 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's original
host id: 1 new host id: null host id before state transition: 1
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total CPU: 45600 and CPU after applying overprovisioning: 912000
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total RAM: 206085242880 and RAM after applying overprovisioning:
4121704792064
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) release
cpu from host: 1, old used: 1800,reserved: 0, actual total: 45600, total with
overprovisioning: 912000; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) release
mem from host: 1, old used: 1073741824,reserved: 0, total: 4121704792064; new
used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2018-09-07 14:19:26,746 ERROR [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Invocation
exception, caused by: java.lang.ArrayIndexOutOfBoundsException
2018-09-07 14:19:26,747 INFO [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Rethrow
exception java.lang.ArrayIndexOutOfBoundsException
^[[1;2D^C
[root@ma-cloud management]# tail -n 1000000000 -f management-server.log | grep
ctx-749d330b
2018-09-07 14:18:35,880 DEBUG [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Execute VM
work job:
com.cloud.vm.VmWorkStart{"dcId":1,"podId":1,"clusterId":1,"hostId":1,"userId":2,"accountId":2,"vmId":172,"handlerName":"VirtualMachineManagerImpl"}
2018-09-07 14:18:35,899 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Stopped to Starting with event: StartRequestedvm's original
host id: 1 new host id: null host id before state transition: null
2018-09-07 14:18:35,900 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully transitioned to start state for VM[User|i-28-172-VM] reservation
id = f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf
2018-09-07 14:18:35,902 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1,
hostId: 1, poolId: null
2018-09-07 14:18:35,902 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Deploy
avoids pods: null, clusters: null, hosts: null
2018-09-07 14:18:35,906 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Root
volume is ready, need to place VM in volume's cluster
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
DeploymentPlanner allocation algorithm: null
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Trying to
allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu:
1800, requested ram: 1073741824
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Is ROOT
volume READY (pool already allocated)?: Yes
2018-09-07 14:18:35,915 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
DeploymentPlan has host_id specified, choosing this host and making no checks
on this host: 1
2018-09-07 14:18:35,916 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Looking
for suitable pools for this host under zone: 1, pod: 1, cluster: 1
2018-09-07 14:18:35,919 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Checking
suitable pools for volume (Id, Type): (183,ROOT)
2018-09-07 14:18:35,919 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Volume has
pool already allocated, checking if pool can be reused, poolId: 2
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Planner
need not allocate a pool for this volume since its READY
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Trying to
find a potenial host and associated storage pools from the suitable host/pool
lists for this VM
2018-09-07 14:18:35,920 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Checking
if host: 1 can access any suitable storage pool for volume: ROOT
2018-09-07 14:18:35,922 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Host: 1
can access pool: 2
2018-09-07 14:18:35,923 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Found a
potential host id: 1 name: ix-mapod01-esx02.stxt.media.int and associated
storage pools for this VM
2018-09-07 14:18:35,924 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Returning
Deployment Destination:
Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2018-09-07 14:18:35,924 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Deployment
found - P0=VM[User|i-28-172-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage()]
2018-09-07 14:18:35,955 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Starting to Starting with event: OperationRetryvm's original
host id: 1 new host id: 1 host id before state transition: null
2018-09-07 14:18:35,955 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM
starting again on the last host it was stopped on
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total CPU: 45600 and CPU after applying overprovisioning: 912000
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) We are
allocating VM, increasing the used capacity of this host:1
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Current
Used CPU: 0 , Free CPU:912000 ,Requested CPU: 1800
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Current
Used RAM: 0 , Free RAM:4121704792064 ,Requested RAM: 1073741824
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) We are
allocating VM to the last host again, so adjusting the reserved capacity if it
is not less than required
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Reserved
CPU: 0 , Requested CPU: 1800
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Reserved
RAM: 0 , Requested RAM: 1073741824
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) CPU STATS
after allocation: for host: 1, old used: 0, old reserved: 0, actual total:
45600, total with overprovisioning: 912000; new used:1800, reserved:0;
requested cpu:1800,alloc_from_last:true
2018-09-07 14:18:35,963 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) RAM STATS
after allocation: for host: 1, old used: 0, old reserved: 0, total:
4121704792064; new used: 1073741824, reserved: 0; requested mem:
1073741824,alloc_from_last:true
2018-09-07 14:18:35,971 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Network
id=224 is already implemented
2018-09-07 14:18:35,984 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:35,988 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Changing
active number of nics for network id=224 on 1
2018-09-07 14:18:35,997 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Asking
VirtualRouter to prepare for
Nic[293-172-f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf-10.1.1.39]
2018-09-07 14:18:36,013 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:36,016 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) CONFIG
DHCP FOR SUBNETS RULES
2018-09-07 14:18:36,027 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:18:36,030 DEBUG [network.topology.AdvancedNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) APPLYING
VPC DHCP ENTRY RULES
2018-09-07 14:18:36,030 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Applying
dhcp entry in network Ntwk[224|Guest|8]
2018-09-07 14:18:36,048 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Sending { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:68:f0:00:01","vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:68:f0:00:01","isDefault":true,"executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:18:36,048 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Executing: { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"02:00:68:f0:00:01","vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","defaultRouter":"10.1.1.1","defaultDns":"10.1.1.1","duid":"00:03:00:01:02:00:68:f0:00:01","isDefault":true,"executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:01,464 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268968: Received: { Ans: , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 110, { GroupAnswer } }
2018-09-07 14:19:01,472 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:01,475 DEBUG [network.topology.AdvancedNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) APPLYING
VPC USERDATA RULES
2018-09-07 14:19:01,475 DEBUG [network.topology.BasicNetworkTopology]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Applying
userdata and password entry in network Ntwk[224|Guest|8]
2018-09-07 14:19:01,485 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Sending { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:01,486 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Executing: { Cmd , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"10.1.1.39","vmName":"pospiemi-10","executeInSequence":true,"accessDetails":{"router.name":"r-1488-VM","router.guest.ip":"10.1.1.1","router.ip":"10.100.10.155","zone.network.type":"Advanced"},"wait":0}}]
}
2018-09-07 14:19:26,429 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
14-7014637894606268969: Received: { Ans: , MgmtId: 345050582394, via:
14(ix-mapod01-esx04.stxt.media.int), Ver: v1, Flags: 110, { GroupAnswer } }
2018-09-07 14:19:26,430 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:26,435 DEBUG [engine.orchestration.VolumeOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) No need to
recreate the volume: Vol[183|vm=172|ROOT], since it already has a pool
assigned: 2, adding disk to VM
2018-09-07 14:19:26,452 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Cleaning
up resources for the vm VM[User|i-28-172-VM] in Starting state
2018-09-07 14:19:26,457 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Sending { Cmd , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-28-172-VM","executeInSequence":false,"wait":0}}]
}
2018-09-07 14:19:26,457 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Executing: { Cmd , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"checkBeforeCleanup":false,"forceStop":false,"volumesToDisconnect":[],"vmName":"i-28-172-VM","executeInSequence":false,"wait":0}}]
}
2018-09-07 14:19:26,692 DEBUG [agent.transport.Request]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Seq
1-2889340635934897591: Received: { Ans: , MgmtId: 345050582394, via:
1(ix-mapod01-esx02.stxt.media.int), Ver: v1, Flags: 10, { StopAnswer } }
2018-09-07 14:19:26,701 DEBUG [cloud.network.NetworkModelImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Service
SecurityGroup is not supported in the network id=224
2018-09-07 14:19:26,704 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Changing
active number of nics for network id=224 on -1
2018-09-07 14:19:26,713 DEBUG [engine.orchestration.NetworkOrchestrator]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Asking
VirtualRouter to release
NicProfile[293-172-f0d1fbbe-6e71-43f5-bd2b-9559ca06e1cf-10.1.1.39-null
2018-09-07 14:19:26,713 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully released network resources for the vm VM[User|i-28-172-VM]
2018-09-07 14:19:26,713 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b)
Successfully cleanued up resources for the vm VM[User|i-28-172-VM] in Starting
state
2018-09-07 14:19:26,724 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) VM state
transitted from :Starting to Stopped with event: OperationFailedvm's original
host id: 1 new host id: null host id before state transition: 1
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total CPU: 45600 and CPU after applying overprovisioning: 912000
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Hosts's
actual total RAM: 206085242880 and RAM after applying overprovisioning:
4121704792064
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) release
cpu from host: 1, old used: 1800,reserved: 0, actual total: 45600, total with
overprovisioning: 912000; new used: 0,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2018-09-07 14:19:26,730 DEBUG [cloud.capacity.CapacityManagerImpl]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) release
mem from host: 1, old used: 1073741824,reserved: 0, total: 4121704792064; new
used: 0,reserved:0; movedfromreserved: false,moveToReserveredfalse
2018-09-07 14:19:26,746 ERROR [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Invocation
exception, caused by: java.lang.ArrayIndexOutOfBoundsException
2018-09-07 14:19:26,747 INFO [cloud.vm.VmWorkJobHandlerProxy]
(Work-Job-Executor-73:ctx-f0153f83 job-31342/job-31343 ctx-749d330b) Rethrow
exception java.lang.ArrayIndexOutOfBoundsException
~~~
[ Full content available at: https://github.com/apache/cloudstack/issues/2838 ]
This message was relayed via gitbox.apache.org for [email protected]
