hong created CLOUDSTACK-719:
-------------------------------
Summary: Vrouter problem SSH auth is Failed
Key: CLOUDSTACK-719
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-719
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: VMware
Affects Versions: 4.0.0
Environment: Centos 6.2 kernel 2.6.32-220.el6.x86_64 , vsphere 5.0
enabled HA functions CS4.0
Reporter: hong
can't start Vrouter when add instances Failed to authentication SSH
the log recoder is :
2012-12-29 15:38:56,215 INFO [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Trying to connect to 192.168.100.5
2012-12-29 15:38:56,216 INFO [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Could not connect to 192.168.100.5 due to
java.net.ConnectException: Connection refused
2012-12-29 15:39:02,216 INFO [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Trying to connect to 192.168.100.5
2012-12-29 15:39:02,220 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Ping command port succeeded for vm r-4-VM
2012-12-29 15:39:02,220 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Execute network usage setup command on r-4-VM
2012-12-29 15:39:02,602 ERROR [utils.ssh.SshHelper]
(DirectAgent-37:192.168.100.130) Failed to authentication SSH user root on host
192.168.100.5
2012-12-29 15:39:02,619 ERROR [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Unable to execute NetworkUsage command on DomR
(192.168.100.5), domR may not be ready yet. failure due to Exception:
java.lang.Exception
Message: Failed to authentication SSH user root on host 192.168.100.5
java.lang.Exception: Failed to authentication SSH user root on host
192.168.100.5
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:144)
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:37)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.networkUsage(VmwareResource.java:4566)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1911)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:425)
at
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:191)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-12-29 15:39:02,620 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Executing resource GetDomRVersionCmd:
{"accessDetails":{"router.ip":"192.168.100.5","router.name":"r-4-VM"},"wait":0}
2012-12-29 15:39:02,621 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Run command on domR 192.168.100.5,
/opt/cloud/bin/get_template_version.sh
2012-12-29 15:39:02,621 DEBUG [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) Use router's private IP for SSH control. IP :
192.168.100.5
2012-12-29 15:39:02,640 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2012-12-29 15:39:02,831 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2012-12-29 15:39:02,889 ERROR [utils.ssh.SshHelper]
(DirectAgent-37:192.168.100.130) Failed to authentication SSH user root on host
192.168.100.5
2012-12-29 15:39:02,891 ERROR [vmware.resource.VmwareResource]
(DirectAgent-37:192.168.100.130) GetDomRVersionCmd failed due to Exception:
java.lang.Exception
Message: Failed to authentication SSH user root on host 192.168.100.5
java.lang.Exception: Failed to authentication SSH user root on host
192.168.100.5
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:144)
at com.cloud.utils.ssh.SshHelper.sshExecute(SshHelper.java:37)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:1753)
at
com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:433)
at
com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:191)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-12-29 15:39:02,893 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-37:null) Seq 1-1207697448: Cancelling because one of the answers
is false and it is stop on error.
2012-12-29 15:39:02,893 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-37:null) Seq 1-1207697448: Response Received:
2012-12-29 15:39:02,894 DEBUG [agent.transport.Request] (DirectAgent-37:null)
Seq 1-1207697448: Processing: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110,
[{"StartAnswer":{"vm":{"id":4,"name":"r-4-VM","bootloader":"HVM","type":"DomainRouter","cpus":1,"speed":500,"minRam":134217728,"maxRam":134217728,"arch":"i686","os":"Debian
GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP name=r-4-VM
eth0ip=192.168.100.5 eth0mask=255.255.255.0 gateway=192.168.100.1
domain=andylhz.com dhcprange=192.168.100.1 eth1ip=0.0.0.0 eth1mask=0.0.0.0
mgmtcidr=192.168.100.0/24 localgw=172.16.100.1 sshonguest=true type=dhcpsrvr
disable_rp_filter=true extra_pubnics=2 dns1=8.8.8.8
nic_macs=06:ae:0a:00:00:35|02:00:39:f2:00:03","rebootOnCrash":false,"enableHA":true,"limitCpuUse":false,"vncPassword":"4980b404b014bc57","params":{"nicAdapter":"E1000"},"uuid":"93f877e7-6017-4469-9215-a85c58d2bc2b","disks":[{"id":5,"name":"ROOT-4","mountPoint":"/primary","path":"ROOT-4","size":2097152000,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"6fa3bd87-fc85-35ad-bba4-129b39d242a3","deviceId":0}],"nics":[{"deviceId":0,"networkRateMbps":200,"defaultNic":true,"uuid":"1840bdd4-75c9-4393-9d08-c2ab2cd0f149","ip":"192.168.100.5","netmask":"255.255.255.0","gateway":"192.168.100.1","mac":"06:ae:0a:00:00:35","dns1":"8.8.8.8","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isolationUri":"ec2://untagged","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"a41c3be5-7287-413b-bff3-14bc2e6a7dbf","ip":"0.0.0.0","netmask":"0.0.0.0","gateway":"0.0.0.0","mac":"02:00:39:f2:00:03","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"check.CheckSshAnswer":{"result":true,"wait":0}},{"GetDomRVersionAnswer":{"result":false,"details":"GetDomRVersionCmd
failed due to Exception: java.lang.Exception\nMessage: Failed to
authentication SSH user root on host 192.168.100.5\n","wait":0}}] }
2012-12-29 15:39:02,895 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697448: Received: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110, { StartAnswer, CheckSshAnswer, GetDomRVersionAnswer } }
2012-12-29 15:39:02,896 DEBUG [agent.manager.AgentAttache]
(DirectAgent-37:null) Seq 1-1207697448: No more commands found
2012-12-29 15:39:02,902 WARN
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-7:job-7)
Unable to get the template/scripts version of router r-4-VM due to:
GetDomRVersionCmd failed due to Exception: java.lang.Exception
Message: Failed to authentication SSH user root on host 192.168.100.5
2012-12-29 15:39:02,902 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) The guru did not like the answers so stopping
VM[DomainRouter|r-4-VM]
2012-12-29 15:39:02,906 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697468: Sending { Cmd , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"r-4-VM","wait":0}}] }
2012-12-29 15:39:02,906 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697468: Executing: { Cmd , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"r-4-VM","wait":0}}] }
2012-12-29 15:39:02,906 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-60:null) Seq 1-1207697468: Executing request
2012-12-29 15:39:02,907 INFO [vmware.resource.VmwareResource]
(DirectAgent-60:192.168.100.130) Executing resource StopCommand:
{"isProxy":false,"vmName":"r-4-VM","wait":0}
2012-12-29 15:39:02,907 DEBUG [vmware.mo.HostMO]
(DirectAgent-60:192.168.100.130) find VM r-4-VM on host
2012-12-29 15:39:02,907 DEBUG [vmware.mo.HostMO]
(DirectAgent-60:192.168.100.130) load VM cache on host
2012-12-29 15:39:03,289 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers.
2012-12-29 15:39:03,749 INFO [vmware.resource.VmwareResource]
(DirectAgent-60:192.168.100.130) Remove all snapshot before stopping VM r-4-VM
2012-12-29 15:39:04,623 INFO [vmware.mo.VirtualMachineMO]
(DirectAgent-60:192.168.100.130) Try gracefully shut down VM r-4-VM
2012-12-29 15:39:17,261 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) VmStatsCollector is running...
2012-12-29 15:39:23,300 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-1:null) Ping from 5
2012-12-29 15:39:26,515 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-60:null) Seq 1-1207697468: Response Received:
2012-12-29 15:39:26,516 DEBUG [agent.transport.Request] (DirectAgent-60:null)
Seq 1-1207697468: Processing: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"Stop VM r-4-VM
Succeed","wait":0}}] }
2012-12-29 15:39:26,516 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697468: Received: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2012-12-29 15:39:26,516 DEBUG [agent.manager.AgentManagerImpl]
(Job-Executor-7:job-7) Details from executing class
com.cloud.agent.api.StopCommand: Stop VM r-4-VM Succeed
2012-12-29 15:39:26,516 ERROR [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Failed to start instance VM[DomainRouter|r-4-VM]
com.cloud.utils.exception.ExecutionException: Unable to start
VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:814)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2352)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1597)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1697)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
at
com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:205)
at
com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2056)
at
com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2172)
at
com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2113)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2601)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2589)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2012-12-29 15:39:26,519 DEBUG [agent.manager.AgentAttache]
(DirectAgent-60:null) Seq 1-1207697468: No more commands found
2012-12-29 15:39:26,521 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Cleaning up resources for the vm VM[DomainRouter|r-4-VM]
in Starting state
2012-12-29 15:39:26,523 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697469: Sending { Cmd , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"r-4-VM","wait":0}}] }
2012-12-29 15:39:26,523 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697469: Executing: { Cmd , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"r-4-VM","wait":0}}] }
2012-12-29 15:39:26,523 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-9:null) Seq 1-1207697469: Executing request
2012-12-29 15:39:26,524 INFO [vmware.resource.VmwareResource]
(DirectAgent-9:192.168.100.130) Executing resource StopCommand:
{"isProxy":false,"vmName":"r-4-VM","wait":0}
2012-12-29 15:39:26,524 DEBUG [vmware.mo.HostMO]
(DirectAgent-9:192.168.100.130) find VM r-4-VM on host
2012-12-29 15:39:26,524 DEBUG [vmware.mo.HostMO]
(DirectAgent-9:192.168.100.130) load VM cache on host
2012-12-29 15:39:27,468 INFO [vmware.resource.VmwareResource]
(DirectAgent-9:192.168.100.130) VM r-4-VM is already in stopped state
2012-12-29 15:39:27,469 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-9:null) Seq 1-1207697469: Response Received:
2012-12-29 15:39:27,469 DEBUG [agent.transport.Request] (DirectAgent-9:null)
Seq 1-1207697469: Processing: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM r-4-VM is
already in stopped state","wait":0}}] }
2012-12-29 15:39:27,469 DEBUG [agent.transport.Request] (Job-Executor-7:job-7)
Seq 1-1207697469: Received: { Ans: , MgmtId: 345052438439, via: 1, Ver: v1,
Flags: 110, { StopAnswer } }
2012-12-29 15:39:27,474 DEBUG [agent.manager.AgentAttache] (DirectAgent-9:null)
Seq 1-1207697469: No more commands found
2012-12-29 15:39:27,494 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-7:job-7)
Successfully updated user statistics as a part of domR VM[DomainRouter|r-4-VM]
reboot/stop
2012-12-29 15:39:27,501 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Service SecurityGroup is not supported in the network
id=204
2012-12-29 15:39:27,506 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking JuniperSRX to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking Netscaler to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking F5BigIP to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking VirtualRouter to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking Ovs to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking ExternalDhcpServer to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking BareMetal to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking SecurityGroupProvider to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking CiscoNexus1000vVSM to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking VpcVirtualRouter to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,507 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking NiciraNvp to release
Nic[9-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-192.168.100.5]
2012-12-29 15:39:27,513 DEBUG [network.guru.ControlNetworkGuru]
(Job-Executor-7:job-7) Released nic: NicProfile[10-4-null-null-null
2012-12-29 15:39:27,516 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking JuniperSRX to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,516 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking Netscaler to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,516 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking F5BigIP to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking VirtualRouter to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking Ovs to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking ExternalDhcpServer to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking BareMetal to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking SecurityGroupProvider to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking CiscoNexus1000vVSM to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking VpcVirtualRouter to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-7:job-7) Asking NiciraNvp to release
Nic[10-4-90900bec-bd8a-4f2c-a6b1-902674a0ed7c-null]
2012-12-29 15:39:27,517 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Successfully released network resources for the vm
VM[DomainRouter|r-4-VM]
2012-12-29 15:39:27,517 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Successfully cleanued up resources for the vm
VM[DomainRouter|r-4-VM] in Starting state
2012-12-29 15:39:27,534 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-7:job-7) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 1
2012-12-29 15:39:27,543 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-7:job-7) Hosts's actual total CPU: 31904 and CPU after applying
overprovisioning: 31904
2012-12-29 15:39:27,544 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-7:job-7) release cpu from host: 1, old used: 1500,reserved: 0,
actual total: 31904, total with overprovisioning: 31904; new used:
1000,reserved:0; movedfromreserved: false,moveToReserveredfalse
2012-12-29 15:39:27,544 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-7:job-7) release mem from host: 1, old used: 1476395008,reserved:
0, total: 8584552448; new used: 1342177280,reserved:0; movedfromreserved:
false,moveToReserveredfalse
2012-12-29 15:39:27,551 INFO [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Unable to contact resource.
com.cloud.exception.AgentUnavailableException: Resource [Host:1] is
unreachable: Host 1: Unable to start instance due to Unable to start
VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:847)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.start(VirtualNetworkApplianceManagerImpl.java:2352)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startVirtualRouter(VirtualNetworkApplianceManagerImpl.java:1597)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.startRouters(VirtualNetworkApplianceManagerImpl.java:1697)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1675)
at
com.cloud.network.element.VirtualRouterElement.prepare(VirtualRouterElement.java:205)
at
com.cloud.network.NetworkManagerImpl.prepareElement(NetworkManagerImpl.java:2056)
at
com.cloud.network.NetworkManagerImpl.prepareNic(NetworkManagerImpl.java:2172)
at
com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2113)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2601)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2589)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at com.cloud.api.commands.DeployVMCmd.execute(DeployVMCmd.java:330)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by: com.cloud.utils.exception.ExecutionException: Unable to start
VM[DomainRouter|r-4-VM] due to error in finalizeStart, not retrying
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:814)
... 28 more
2012-12-29 15:39:27,557 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-7:job-7) Cleaning up resources for the vm
VM[User|6440f46d-6917-4c1d-a950-0dbf0db64aff] in Starting state
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
