Sudhansu Sahu created CLOUDSTACK-7986:
-----------------------------------------
Summary: [F5 LB] Failed to execute IPAssocCommand due to
com.cloud.utils.exception.ExecutionException: Exception caught in
Networking::urn:iControl:Networking/VLAN::create()
Key: CLOUDSTACK-7986
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-7986
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Network Devices
Affects Versions: 4.4.0, 4.3.0, 4.5.0
Environment: Red Hat Enterprise Linux Server release 6.3 (Santiago)
IG-IP 11.3.0 Build 39.0 VE Trial 11.3.0-HF1 (based on BIGIP 11.3.0HF6)
Reporter: Sudhansu Sahu
When trying to launch a VM on a network that uses the network offering (with LB
provided by the F5) the following errors are observed in the logs and the
creation ultimately fails:
{noformat}
71831 2014-11-26 12:19:34,403 DEBUG
[c.c.n.ExternalLoadBalancerDeviceManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Allocated
external load balancer device:1 for the network: 205
71832 2014-11-26 12:19:34,428 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Seq
4-5343239482898383377: Sending { Cmd , MgmtId: 7407677735140, via:
4(200-F5BigIpLoadBalancer-10.147.60.5 1), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"910","vlanGateway":"10.0.160.37","vla
nNetmask":"255.255.240.0","networkRate":200,"newNic":false}],"accessDetails":{},"wait":0}}]
}
71833 2014-11-26 12:19:34,429 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Seq
4-5343239482898383377: Executing: { Cmd , MgmtId: 7407677735140, via:
4(200-F5BigIpLoadBalancer-10.147.6 0.51), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":false,"broadcastUri":"910","vlanGateway":"10.0.160.37","
vlanNetmask":"255.255.240.0","networkRate":200,"newNic":false}],"accessDetails":{},"wait":0}}]
}
71834 2014-11-26 12:19:34,429 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-217:ctx-40025c4d) Seq 4-5343239482898383377: Executing request
71835 2014-11-26 12:19:34,731 DEBUG [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Creating a guest VLAN with tag 910
71836 2014-11-26 12:19:35,616 DEBUG [c.c.a.ApiServlet]
(catalina-exec-19:ctx-6bfff176) ===START=== 10.252.192.47 -- GET
command=queryAsyncJobResult&jobId=33e182fe-ab28-470c-a483-a16bd40e05d9&response=json&sessionkey=cUbJKOPdiHo
sLJ06cqS8y66FEMU%3D&_=1416984574574
71837 2014-11-26 12:19:35,711 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Failed to execute IPAssocCommand due to
com.cloud.utils.exception.ExecutionException: Failed to create vlan with tag 910
71838 2014-11-26 12:19:35,734 DEBUG [c.c.a.ApiServlet]
(catalina-exec-19:ctx-6bfff176 ctx-f76b168b) ===END=== 10.252.192.47 -- GET
command=queryAsyncJobResult&jobId=33e182fe-ab28-470c-a483-a16bd40e05d9&response=json&sessionkey=
cUbJKOPdiHosLJ06cqS8y66FEMU%3D&_=1416984574574
71839 2014-11-26 12:19:35,842 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Retrying IpAssocCommand. Number of retries
remaining: 1
71840 2014-11-26 12:19:36,053 DEBUG [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Creating a guest VLAN with tag 910
71841 2014-11-26 12:19:36,233 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Exception caught in
Networking::urn:iControl:Networking/VLAN::create()
71842 Exception: Common::OperationFailed
71843 primary_error_code : 16908390 (0x01020066)
71844 secondary_error_code : 0
71845 error_string : 01020066:3: The requested VLAN
(/Common/vlan-910) already exists in partition Common.
71846 2014-11-26 12:19:36,234 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Failed to execute IPAssocCommand due to
com.cloud.utils.exception.ExecutionException: Exception caught in
Networking::urn:iControl:Netwo rking/VLAN::create()
71847 Exception: Common::OperationFailed
71848 primary_error_code : 16908390 (0x01020066)
71849 secondary_error_code : 0
71850 error_string : 01020066:3: The requested VLAN
(/Common/vlan-910) already exists in partition Common.
71851 2014-11-26 12:19:36,318 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Retrying IpAssocCommand. Number of retries
remaining: 0
71852 2014-11-26 12:19:36,529 DEBUG [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Creating a guest VLAN with tag 910
71853 2014-11-26 12:19:36,562 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Exception caught in
Networking::urn:iControl:Networking/VLAN::create()
71854 Exception: Common::OperationFailed
71855 primary_error_code : 16908390 (0x01020066)
71856 secondary_error_code : 0
71857 error_string : 01020066:3: The requested VLAN
(/Common/vlan-910) already exists in partition Common.
71858 2014-11-26 12:19:36,563 ERROR [c.c.n.r.F5BigIpResource]
(DirectAgent-217:ctx-40025c4d) Failed to execute IPAssocCommand due to
com.cloud.utils.exception.ExecutionException: Exception caught in
Networking::urn:iControl:Netwo rking/VLAN::create()
71859 Exception: Common::OperationFailed
71860 primary_error_code : 16908390 (0x01020066)
71861 secondary_error_code : 0
71862 error_string : 01020066:3: The requested VLAN
(/Common/vlan-910) already exists in partition Common.
71863 2014-11-26 12:19:36,563 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-217:ctx-40025c4d) Seq 4-5343239482898383377: Response Received:
71864 2014-11-26 12:19:36,563 DEBUG [c.c.a.t.Request]
(DirectAgent-217:ctx-40025c4d) Seq 4-5343239482898383377: Processing: { Ans: ,
MgmtId: 7407677735140, via: 4, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.routing.IpAssocAnswer
":{"results":["Failed"],"result":false,"wait":0}}] }
71865 2014-11-26 12:19:36,563 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Seq
4-5343239482898383377: Received: { Ans: , MgmtId: 7407677735140, via: 4, Ver:
v1, Flags: 10, { IpAssocAn swer } }
71866 2014-11-26 12:19:36,563 ERROR
[c.c.n.ExternalLoadBalancerDeviceManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) External load
balancer was unable to implement the guest network on the external load
balancer in zone bpkvmwstorezone
71867 2014-11-26 12:19:36,570 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Cleaning up
because we're unable to implement the network Ntwk[205|Guest|15]
71868 2014-11-26 12:19:36,589 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Lock is
acquired for network Ntwk[205|Guest|15] as a part of network shutdown
71869 2014-11-26 12:19:36,597 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Releasing 0
port forwarding rules for network id=205 as a part of shutdownNetworkRules
71870 2014-11-26 12:19:36,598 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
rules to forward to the network elements
71871 2014-11-26 12:19:36,599 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Releasing 0
static nat rules for network id=205 as a part of shutdownNetworkRules
71872 2014-11-26 12:19:36,599 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
rules to forward to the network elements
71873 2014-11-26 12:19:36,601 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Revoking 0
Public load balancing rules for network id=205
71874 2014-11-26 12:19:36,601 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
Load Balancing Rules to forward to the network elements
71875 2014-11-26 12:19:36,602 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Revoking 0
Internal load balancing rules for network id=205
71876 2014-11-26 12:19:36,603 DEBUG [c.c.n.l.LoadBalancingRulesManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
Load Balancing Rules to forward to the network elements
71877 2014-11-26 12:19:36,604 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Releasing 0
firewall ingress rules for network id=205 as a part of shutdownNetworkRules
71878 2014-11-26 12:19:36,604 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
rules to forward to the network elements
71879 2014-11-26 12:19:36,606 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Releasing 0
firewall egress rules for network id=205 as a part of shutdownNetworkRules
71880 2014-11-26 12:19:36,607 DEBUG [c.c.n.f.FirewallManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) There are no
rules to forward to the network elements
71881 2014-11-26 12:19:36,609 DEBUG [c.c.n.r.RulesManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Found 0
static nat rules to apply for network id 205
71882 2014-11-26 12:19:36,631 DEBUG [c.c.n.e.VirtualRouterElement]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Virtual
router elemnt doesn't need to associate ip addresses on the backend; virtual
router does n't exist in the network 205
71883 2014-11-26 12:19:36,632 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Sending
network shutdown to F5BigIP
71884 2014-11-26 12:19:36,648 WARN
[c.c.n.ExternalLoadBalancerDeviceManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Network
shutdwon requested on external load balancer element, which did not imple
ment the network. Either network implement failed half way through or already
network shutdown is completed. So just returning.
71885 2014-11-26 12:19:36,656 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Sending
network shutdown to VirtualRouter
71886 2014-11-26 12:19:36,673 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Network
id=205 is shutdown successfully, cleaning up corresponding resources now.
71887 2014-11-26 12:19:36,676 DEBUG [c.c.n.g.GuestNetworkGuru]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Releasing
vnet for the network id=205
71888 2014-11-26 12:19:36,710 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Lock is
released for network Ntwk[205|Guest|15] as a part of network shutdown
71889 2014-11-26 12:19:36,710 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Lock is
released for network id 205 as a part of network implement
71890 2014-11-26 12:19:36,711 INFO [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) Unable to
contact resource.
71891 com.cloud.exception.ResourceUnavailableException: Resource [Network:205]
is unreachable: External load balancer was unable to implement the guest
network on the external load balancer in zone bpkvmwstorezone
71892 at
com.cloud.network.ExternalLoadBalancerDeviceManagerImpl.manageGuestNetworkWithExternalLoadBalancer(ExternalLoadBalancerDeviceManagerImpl.java:1058)
71893 at
com.cloud.network.element.F5ExternalLoadBalancerElement.implement(F5ExternalLoadBalancerElement.java:158)
71894 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetworkElementsAndResources(NetworkOrchestrator.java:1101)
71895 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1008)
71896 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:938)
71897 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1293)
71898 at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:983)
71899 at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4436)
71900 at sun.reflect.GeneratedMethodAccessor300.invoke(Unknown Source)
71901 at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
71902 at java.lang.reflect.Method.invoke(Method.java:601)
71903 at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
71904 at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4592)
71905 at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
71906 at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:536)
71907 at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
71908 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
71909 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
71910 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
71911 at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
71912 at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:493)
71913 at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
71914 at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
71915 at java.util.concurrent.FutureTask.run(FutureTask.java:166)
71916 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
71917 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
71918 at java.lang.Thread.run(Thread.java:722)
71919 2014-11-26 12:19:36,712 WARN [c.c.v.VirtualMachineManagerImpl]
(Work-Job-Executor-133:ctx-434a0b57 job-269/job-270 ctx-cd8df97f) unexpected
ResourceUnavailableException : com.cloud.network.Network
71920 com.cloud.exception.ResourceUnavailableException: Resource [Network:205]
is unreachable: External load balancer was unable to implement the guest
network on the external load balancer in zone bpkvmwstorezone
71921 at
com.cloud.network.ExternalLoadBalancerDeviceManagerImpl.manageGuestNetworkWithExternalLoadBalancer(ExternalLoadBalancerDeviceManagerImpl.java:1058)
71922 at
com.cloud.network.element.F5ExternalLoadBalancerElement.implement(F5ExternalLoadBalancerElement.java:158)
71923 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetworkElementsAndResources(NetworkOrchestrator.java:1101)
71924 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:1008)
71925 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.implementNetwork(NetworkOrchestrator.java:938)
71926 at
org.apache.cloudstack.engine.orchestration.NetworkOrchestrator.prepare(NetworkOrchestrator.java:1293)
71927 at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:983)
71928 at
com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:4436)
71929 at sun.reflect.GeneratedMethodAccessor300.invoke(Unknown Source)
71930 at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
71931 at java.lang.reflect.Method.invoke(Method.java:601)
71932 at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
71933 at
com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:4592)
71934 at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:103)
71935 at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:536)
71936 at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
71937 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
71938 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
71939 at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
71940 at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
71941 at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:493)
71942 at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
71943 at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
71944 at java.util.concurrent.FutureTask.run(FutureTask.java:166)
71945 at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
71946 at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
71947 at java.lang.Thread.run(Thread.java:722)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
