Abhinav Roy created CLOUDSTACK-126:
--------------------------------------
Summary: IP allocation on an existing Network after upgrading from
CS 3.0.2 to ASF 4.0 fails with "ResourceUnavailableException: Resource
[DataCenter:1] is unreachable: Unable to apply ip association on router"
Key: CLOUDSTACK-126
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-126
Project: CloudStack
Issue Type: Bug
Components: Network Controller, Network Devices
Affects Versions: pre-4.0.0
Environment: MS OS : Rhel 6.2
Hypervisor : Xen 6.0.2
BUILDs : 3.0.2 and ASF 4.0 [ Git Revision:
54f9af1695bc359b02e9fc906b3b335cc0bfec41 Git URL:
https://git-wip-us.apache.org/repos/asf/incubator-cloudstack.git]
Reporter: Abhinav Roy
Fix For: pre-4.0.0
Steps :
=========================
1. Deploy an advanced zone setup with CS 3.0.2
2. Deploy couple of VMs.
3. Acquire an IP Address for the Network created.
4. Upgrade the setup to ASF 4.0
5. Create a VM on the existing Network.
6. Acquire one more IP Address on the existing Network.
Expected Behaviour :
=========================
All the steps should be successful and no error should be seen.
Observed Behaviour :
=========================
1. Steps 6 fails with the following exceptions
2012-09-18 00:32:25,151 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-24:null) Associate IP address called by the user 2 account 2
2012-09-18 00:32:25,154 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-24:null) Associate IP address lock acquired
2012-09-18 00:32:25,157 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-24:null) Got 10.102.125.65 to assign for account 2 in zone 1
2012-09-18 00:32:25,160 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-24:null) Releasing lock account Acct[2-admin]
2012-09-18 00:32:25,161 DEBUG [cloud.network.NetworkManagerImpl]
(catalina-exec-24:null) Associate IP address lock released
2012-09-18 00:32:25,196 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-24:null) submit async job-19, details: AsyncJobVO {id:19,
userId: 2, accountId: 2, sessionKey: null, instanceType: IpAddress, instanceId:
1, cmd: com.cloud.api.commands.AssociateIPAddrCmd, cmdOriginator: null,
cmdInfo:
{"id":"1","response":"json","sessionkey":"8hzazFr/yI02O3oGDZOuHcC4BWI\u003d","ctxUserId":"2","_":"1347908545066","ctxAccountId":"2","networkid":"df48bccd-f675-4a66-adf8-eea5a441b4f3","ctxStartEventId":"74"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 160940036302157,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2012-09-18 00:32:25,201 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-19) Executing com.cloud.api.commands.AssociateIPAddrCmd for
job-19
2012-09-18 00:32:25,208 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-19) Sync job-19 execution on object network.204
2012-09-18 00:32:25,216 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-19) job com.cloud.api.commands.AssociateIPAddrCmd for
job-19 was queued, processing the queue.
2012-09-18 00:32:25,225 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-19) Executing sync queue item: SyncQueueItemVO {id:6,
queueId: 1, contentType: AsyncJob, contentId: 19, lastProcessMsid:
160940036302157, lastprocessNumber: 5, created: Tue Sep 18 00:32:25 IST 2012}
2012-09-18 00:32:25,226 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-8:job-19) Schedule queued job-19
2012-09-18 00:32:25,240 DEBUG [cloud.async.SyncQueueManagerImpl]
(Job-Executor-8:job-19) There is a pending process in sync queue(id: 1)
2012-09-18 00:32:25,242 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-9:job-19) Executing com.cloud.api.commands.AssociateIPAddrCmd for
job-19
2012-09-18 00:32:25,274 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-9:job-19) Associating ip Ip[10.102.125.65-1] to network
Ntwk[204|Guest|7]
2012-09-18 00:32:25,327 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-19)
Applying ip association in network Ntwk[204|Guest|7]
2012-09-18 00:32:25,374 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573732: Sending { Cmd , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 100001,
[{"routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.102.125.69","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:0d:ee:00:00:09","networkRate":200,"trafficType":"Public"},{"accountId":2,"publicIp":"10.102.125.66","sourceNat":false,"add":true,"oneToOneNat":false,"firstIP":false,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:2c:c0:00:00:06","networkRate":200,"trafficType":"Public"}],"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.233","router.name":"r-4-VM"},"wait":0}}]
}
2012-09-18 00:32:25,376 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573732: Executing: { Cmd , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 100001,
[{"routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.102.125.69","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:0d:ee:00:00:09","networkRate":200,"trafficType":"Public"},{"accountId":2,"publicIp":"10.102.125.66","sourceNat":false,"add":true,"oneToOneNat":false,"firstIP":false,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:2c:c0:00:00:06","networkRate":200,"trafficType":"Public"}],"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.233","router.name":"r-4-VM"},"wait":0}}]
}
2012-09-18 00:32:25,379 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-22:null) Seq 1-2076573732: Executing request
2012-09-18 00:32:25,909 ERROR [xen.resource.CitrixResourceBase]
(DirectAgent-22:null) Ip Assoc failure on applying one ip due to exception:
com.cloud.exception.InternalErrorException: Xen plugin "ipassoc" failed.
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.assignPublicIpAddress(CitrixResourceBase.java:1934)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2030)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:421)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
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-09-18 00:32:25,910 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-22:null) Seq 1-2076573732: Response Received:
2012-09-18 00:32:25,910 DEBUG [agent.transport.Request] (DirectAgent-22:null)
Seq 1-2076573732: Processing: { Ans: , MgmtId: 160940036302157, via: 1, Ver:
v1, Flags: 0,
[{"routing.IpAssocAnswer":{"results":["Failed",null],"result":false,"wait":0}}]
}
2012-09-18 00:32:25,911 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573732: Received: { Ans: , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 0, { IpAssocAnswer } }
2012-09-18 00:32:25,911 WARN [cloud.network.NetworkManagerImpl]
(Job-Executor-9:job-19) Failed to associate ip address, so releasing ip from
the database Ip[10.102.125.65-1]
2012-09-18 00:32:25,938 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-9:job-19)
Applying ip association in network Ntwk[204|Guest|7]
2012-09-18 00:32:25,962 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573733: Sending { Cmd , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 100001,
[{"routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.102.125.69","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:31:b6:00:00:09","networkRate":200,"trafficType":"Public"},{"accountId":2,"publicIp":"10.102.125.66","sourceNat":false,"add":true,"oneToOneNat":false,"firstIP":false,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:b7:ca:00:00:06","networkRate":200,"trafficType":"Public"}],"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.233","router.name":"r-4-VM"},"wait":0}}]
}
2012-09-18 00:32:25,963 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573733: Executing: { Cmd , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 100001,
[{"routing.IpAssocCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10.102.125.69","sourceNat":true,"add":true,"oneToOneNat":false,"firstIP":true,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:31:b6:00:00:09","networkRate":200,"trafficType":"Public"},{"accountId":2,"publicIp":"10.102.125.66","sourceNat":false,"add":true,"oneToOneNat":false,"firstIP":false,"vlanId":"untagged","vlanGateway":"10.102.125.1","vlanNetmask":"255.255.255.0","vifMacAddress":"06:b7:ca:00:00:06","networkRate":200,"trafficType":"Public"}],"accessDetails":{"router.guest.ip":"10.1.1.1","zone.network.type":"Advanced","router.ip":"169.254.2.233","router.name":"r-4-VM"},"wait":0}}]
}
2012-09-18 00:32:25,964 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-7:null) Seq 1-2076573733: Executing request
2012-09-18 00:32:26,511 ERROR [xen.resource.CitrixResourceBase]
(DirectAgent-7:null) Ip Assoc failure on applying one ip due to exception:
com.cloud.exception.InternalErrorException: Xen plugin "ipassoc" failed.
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.assignPublicIpAddress(CitrixResourceBase.java:1934)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.execute(CitrixResourceBase.java:2030)
at
com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:421)
at
com.cloud.hypervisor.xen.resource.XenServer56Resource.executeRequest(XenServer56Resource.java:73)
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-09-18 00:32:26,512 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-7:null) Seq 1-2076573733: Response Received:
2012-09-18 00:32:26,513 DEBUG [agent.transport.Request] (DirectAgent-7:null)
Seq 1-2076573733: Processing: { Ans: , MgmtId: 160940036302157, via: 1, Ver:
v1, Flags: 0,
[{"routing.IpAssocAnswer":{"results":["Failed",null],"result":false,"wait":0}}]
}
2012-09-18 00:32:26,513 DEBUG [agent.transport.Request] (Job-Executor-9:job-19)
Seq 1-2076573733: Received: { Ans: , MgmtId: 160940036302157, via: 1, Ver: v1,
Flags: 0, { IpAssocAnswer } }
2012-09-18 00:32:26,513 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-9:job-19) Resource is not available: VirtualRouter
com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is
unreachable: Unable to apply ip association on router
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.applyRules(VirtualNetworkApplianceManagerImpl.java:3135)
at
com.cloud.network.router.VirtualNetworkApplianceManagerImpl.associatePublicIP(VirtualNetworkApplianceManagerImpl.java:2983)
at
com.cloud.network.router.VpcVirtualNetworkApplianceManagerImpl.associatePublicIP(VpcVirtualNetworkApplianceManagerImpl.java:551)
at
com.cloud.network.element.VirtualRouterElement.applyIps(VirtualRouterElement.java:435)
at
com.cloud.network.NetworkManagerImpl.applyIpAssociations(NetworkManagerImpl.java:966)
at
com.cloud.network.NetworkManagerImpl.applyIpAssociations(NetworkManagerImpl.java:647)
at
com.cloud.network.NetworkManagerImpl.associateIPToGuestNetwork(NetworkManagerImpl.java:1208)
at
com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34)
at
com.cloud.network.NetworkManagerImpl.associateIPToNetwork(NetworkManagerImpl.java:7150)
at
com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36)
at
com.cloud.api.commands.AssociateIPAddrCmd.execute(AssociateIPAddrCmd.java:245)
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-09-18 00:32:26,534 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-9:job-19) Complete async job-19, jobStatus: 2, resultCode: 530,
result: Error Code: 534 Error text: Resource [DataCenter:1] is unreachable:
Unable to apply ip association on router
2012-09-18 00:32:26,556 DEBUG [cloud.async.SyncQueueManagerImpl]
(Job-Executor-9:job-19) Sync queue (1) is currently empty
2012-09-18 00:32:29,732 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet
2012-09-18 00:32:30,282 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 2 routers.
2012-09-18 00:32:30,308 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-23:null) Async job-19 completed
2. If we create a new Network after upgrade and then repeat step 6 then this
error is not seen and the IP allocation is successful.
--
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
