You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cloudstack.apache.org by GitBox <gi...@apache.org> on 2018/09/07 13:21:58 UTC
[GitHub] resmo opened a new issue #2838: BLOCKER: 4.11.1: VMware: VM start
fails with ArrayIndexOutOfBoundsException
resmo opened a new issue #2838: BLOCKER: 4.11.1: VMware: VM start fails with ArrayIndexOutOfBoundsException
URL: https://github.com/apache/cloudstack/issues/2838
<!--
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
~~~
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
With regards,
Apache Git Services