[
https://issues.apache.org/jira/browse/CLOUDSTACK-719?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13541239#comment-13541239
]
Musayev, Ilya commented on CLOUDSTACK-719:
------------------------------------------
Hong,
There are few reasons as to why this may happen, in my case I had the issue
with APR.
Please try the following.
Ping the link local ip of the router from CS host. If ping fails, login to
router vm via root (root/6m1ll10n) and ping the CS host from router vm.
Assuming ping is successful, try pinging from CS to router VM once more and see
what happens. Once ping works both ways proceed.
If router VM is now reachable via ping, try to provision the instance and see
if it helps..
Let me know the outcome.
Regards
Ilya
"hong (JIRA)" <j...@apache.org> wrote:
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
> 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
