[
https://issues.apache.org/jira/browse/CLOUDSTACK-126?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Abhinav Roy updated CLOUDSTACK-126:
-----------------------------------
Attachment: management-server.log
Attaching management server log
> 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
>
> Attachments: management-server.log
>
>
> 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
