[
https://issues.apache.org/jira/browse/CLOUDSTACK-7997?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14232687#comment-14232687
]
Jayapal Reddy commented on CLOUDSTACK-7997:
-------------------------------------------
Hi Chandhan,
Can you please send the agent logs ?
For the exception like 'ResourceUnavailableException: Resource [Pod:1] is
unreachable: Unable to apply dhcp entry on router ' there are two reasons.
1. Router is not reachable to due some reason (host down, network issue or keys
issue in the router)
2. Script failure.
For this exceptions only MS logs will not help. Needs agents logs also.
If setup is available I would recommend QA to run the script on the VR with
args and find the script failures if any.
> [Automation] Deployment of VM is failing on Basic Zone in Few Cases - Unable
> to apply dhcp entry on router
> ----------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-7997
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7997
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Automation
> Affects Versions: 4.5.0
> Reporter: Chandan Purushothama
> Assignee: Jayapal Reddy
> Priority: Critical
> Fix For: 4.5.0
>
> Attachments: management-server.zip
>
>
> VM Deployment failure occurred multiple times. Posting the details from one
> such occurrence below:
> =============================
> Unable to apply dhcp entry on router:
> =============================
> {noformat}
> 2014-12-01 18:57:12,396 DEBUG [o.a.c.e.o.NetworkOrchestrator]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Asking VirtualRouter to prepare for
> Nic[132-125-5e3877b8-7029-4029-be70-429a6e47d568-10.219.197.222]
> 2014-12-01 18:57:12,405 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Lock is acquired for network id 204 as a part of router
> startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(152|ROOT-->Pool(1))]
> 2014-12-01 18:57:12,408 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Lock is released for network id 204 as a part of router
> startup in
> Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
> : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(2)-Storage(Volume(152|ROOT-->Pool(1))]
> 2014-12-01 18:57:12,431 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Applying dhcp entry in network Ntwk[204|Guest|6]
> 2014-12-01 18:57:12,446 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Seq 2-1882786119217578814: Sending { Cmd , MgmtId:
> 195740251462904, via: 2(technetium), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:26:ea:00:00:37","vmIpAddress":"10.219.197.222","vmName":"VM-2656bcb0-f793-4248-8256-1754ebe2c2ef","defaultRouter":"10.219.192.1","defaultDns":"10.219.197.221","duid":"00:03:00:01:06:26:ea:00:00:37","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"10.219.197.221","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.3.164"},"wait":0}}]
> }
> 2014-12-01 18:57:12,447 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Seq 2-1882786119217578814: Executing: { Cmd , MgmtId:
> 195740251462904, via: 2(technetium), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:26:ea:00:00:37","vmIpAddress":"10.219.197.222","vmName":"VM-2656bcb0-f793-4248-8256-1754ebe2c2ef","defaultRouter":"10.219.192.1","defaultDns":"10.219.197.221","duid":"00:03:00:01:06:26:ea:00:00:37","isDefault":true,"executeInSequence":false,"accessDetails":{"router.guest.ip":"10.219.197.221","zone.network.type":"Basic","router.name":"r-4-VM","router.ip":"169.254.3.164"},"wait":0}}]
> }
> 2014-12-01 18:57:12,447 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-239:ctx-e27e7d7a) (logid:312cfd5b) Seq 2-1882786119217578814:
> Executing request
> 2014-12-01 18:57:12,447 DEBUG [c.c.h.x.r.CitrixResourceBase]
> (DirectAgent-239:ctx-e27e7d7a) (logid:a7cfe505) Executing command in VR:
> /opt/cloud/bin/router_proxy.sh edithosts.sh 169.254.3.164 -m
> 06:26:ea:00:00:37 -4 10.219.197.222 -h
> VM-2656bcb0-f793-4248-8256-1754ebe2c2ef -d 10.219.192.1 -n 10.219.197.221
> 2014-12-01 18:57:12,448 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-239:ctx-e27e7d7a) (logid:a7cfe505) Seq 2-1882786119217578814:
> Response Received:
> 2014-12-01 18:57:12,449 DEBUG [c.c.a.t.Request]
> (DirectAgent-239:ctx-e27e7d7a) (logid:a7cfe505) Seq 2-1882786119217578814:
> Processing: { Ans: , MgmtId: 195740251462904, via: 2, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":false,"details":"There was a problem
> while connecting to 10.219.195.58:22","wait":0}}] }
> 2014-12-01 18:57:12,449 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Seq 2-1882786119217578814: Received: { Ans: , MgmtId:
> 195740251462904, via: 2, Ver: v1, Flags: 10, { Answer } }
> 2014-12-01 18:57:12,449 INFO [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Unable to contact resource.
> com.cloud.exception.ResourceUnavailableException: Resource [Pod:1] is
> unreachable: Unable to apply dhcp entry on router
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:4086)
> at
> com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyDhcpEntry(VirtualNetworkApplianceManagerImpl.java:3205)
> at sun.reflect.GeneratedMethodAccessor399.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
> at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)
> at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
> at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> at $Proxy191.applyDhcpEntry(Unknown Source)
> at
> com.cloud.network.element.VirtualRouterElement.addDhcpEntry(VirtualRouterElement.java:920)
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareElement(NetworkOrchestrator.java:1242)
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepareNic(NetworkOrchestrator.java:1367)
> at
> org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1303)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:983)
> at
> com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4439)
> at sun.reflect.GeneratedMethodAccessor387.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:601)
> at
> com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
> at
> com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4595)
> at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:546)
> at
> org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at
> org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at
> org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:497)
> 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:722)
> 2014-12-01 18:57:12,463 DEBUG [c.c.v.VirtualMachineManagerImpl]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Cleaning up resources for the vm VM[User|i-179-125-VM] in
> Starting state
> 2014-12-01 18:57:12,466 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Seq 2-1882786119217578815: Sending { Cmd , MgmtId:
> 195740251462904, via: 2(technetium), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-179-125-VM","wait":0}}]
> }
> 2014-12-01 18:57:12,466 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-98:ctx-eb573b61 job-1170/job-1171 ctx-4477fe15)
> (logid:a7cfe505) Seq 2-1882786119217578815: Executing: { Cmd , MgmtId:
> 195740251462904, via: 2(technetium), Ver: v1, Flags: 100011,
> [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-179-125-VM","wait":0}}]
> }
> 2014-12-01 18:57:12,466 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgent-475:ctx-cdced4ad) (logid:fd6ea3f2) Seq 2-1882786119217578815:
> Executing request
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
