You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Venkata Siva Vijayendra Bhamidipati (JIRA)" <ji...@apache.org> on 2013/07/12 18:37:56 UTC
[jira] [Commented] (CLOUDSTACK-719) Vrouter problem SSH auth is
Failed
[ https://issues.apache.org/jira/browse/CLOUDSTACK-719?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13707071#comment-13707071 ]
Venkata Siva Vijayendra Bhamidipati commented on CLOUDSTACK-719:
----------------------------------------------------------------
Just an fyi, this problem is seen if a stale systemvm.iso remains in the secondary storage's systemvm directory, which is why with a new setup, you probably cleared it up and didn't encounter this issue again.
> 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
> Labels: vRouter
>
> 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