Return-Path: X-Original-To: apmail-cloudstack-issues-archive@www.apache.org Delivered-To: apmail-cloudstack-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id EAFA8C109 for ; Mon, 3 Jun 2013 09:46:20 +0000 (UTC) Received: (qmail 88879 invoked by uid 500); 3 Jun 2013 09:46:20 -0000 Delivered-To: apmail-cloudstack-issues-archive@cloudstack.apache.org Received: (qmail 88850 invoked by uid 500); 3 Jun 2013 09:46:20 -0000 Mailing-List: contact issues-help@cloudstack.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@cloudstack.apache.org Delivered-To: mailing list issues@cloudstack.apache.org Received: (qmail 88715 invoked by uid 500); 3 Jun 2013 09:46:20 -0000 Delivered-To: apmail-incubator-cloudstack-issues@incubator.apache.org Received: (qmail 88712 invoked by uid 99); 3 Jun 2013 09:46:20 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 03 Jun 2013 09:46:20 +0000 Date: Mon, 3 Jun 2013 09:46:20 +0000 (UTC) From: "Abhinav Roy (JIRA)" To: cloudstack-issues@incubator.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (CLOUDSTACK-2809) [N-tier : Internal LB between VPC tiers] VM deployment fails for a VPC tier with a network offering having InternalLB as a supported service but no Network ACL MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/CLOUDSTACK-2809?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Abhinav Roy updated CLOUDSTACK-2809: ------------------------------------ Attachment: management-server.log Attaching management server log > [N-tier : Internal LB between VPC tiers] VM deployment fails for a VPC tier with a network offering having InternalLB as a supported service but no Network ACL > --------------------------------------------------------------------------------------------------------------------------------------------------------------- > > Key: CLOUDSTACK-2809 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2809 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the default.) > Components: Network Controller > Affects Versions: 4.2.0 > Reporter: Abhinav Roy > Assignee: Alena Prokharchyk > Fix For: 4.2.0 > > Attachments: management-server.log > > > Steps : > =================== > 1. Create a network offering with the following service capabilities : Dhcp: VpcVirtualRouter, Lb: InternalLbVm, SourceNat: VpcVirtualRouter, Dns: VpcVirtualRouter > 2. Create a VPC tier with this network offering. > 3. Deploy a vm in that VPC tier > Expected behaviour : > ================== > The vm deployment should be successful. > Observed behaviour : > =================== > VM deployment fails with > 2013-06-03 13:28:27,384 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM > 2013-06-03 13:28:27,385 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking if host: 1 can access any suitable storage pool for volume: ROOT > 2013-06-03 13:28:27,386 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Host: 1 can access pool: 1 > 2013-06-03 13:28:27,388 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Found a potential host id: 1 name: xen61-band17 and associated storage pools for this VM > 2013-06-03 13:28:27,390 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(1))] > 2013-06-03 13:28:27,409 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null > 2013-06-03 13:28:27,410 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully transitioned to start state for VM[User|v1tier3] reservation id = cfd3c3e6-9869-4db3-826e-6062a9654248 > 2013-06-03 13:28:27,414 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Trying to deploy VM, vm has dcId: 1 and podId: null > 2013-06-03 13:28:27,414 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) advanceStart: DeploymentPlan is provided, using dcId:1, podId: 1, clusterId: 1, hostId: 1, poolId: null > 2013-06-03 13:28:27,414 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: null > 2013-06-03 13:28:27,426 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: null > 2013-06-03 13:28:27,427 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_907b054a@78c218ac > 2013-06-03 13:28:27,427 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1000, requested ram: 1073741824 > 2013-06-03 13:28:27,427 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Is ROOT volume READY (pool already allocated)?: No > 2013-06-03 13:28:27,427 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1 > 2013-06-03 13:28:27,429 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Looking for suitable pools for this host under zone: 1, pod: 1, cluster: 1 > 2013-06-03 13:28:27,431 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking suitable pools for volume (Id, Type): (8,ROOT) > 2013-06-03 13:28:27,431 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) We need to allocate new storagepool for this volume > 2013-06-03 13:28:27,431 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Calling StoragePoolAllocators to find suitable pools > 2013-06-03 13:28:27,495 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-17:job-17) Checking pool: 1 for volume allocation [Vol[8|vm=8|ROOT]], maxSize : 1759218630656, totalAllocatedSize : 76673156096, askingSize : 21474836480, allocated disable threshold: 0.85 > 2013-06-03 13:28:27,496 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM > 2013-06-03 13:28:27,496 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking if host: 1 can access any suitable storage pool for volume: ROOT > 2013-06-03 13:28:27,497 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Host: 1 can access pool: 1 > 2013-06-03 13:28:27,499 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Found a potential host id: 1 name: xen61-band17 and associated storage pools for this VM > 2013-06-03 13:28:27,500 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(1))] > 2013-06-03 13:28:27,500 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Deployment found - P0=VM[User|v1tier3], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(1))] > 2013-06-03 13:28:27,510 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total CPU: 19152 and CPU after applying overprovisioning: 19152 > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) We are allocating VM, increasing the used capacity of this host:1 > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Current Used CPU: 4000 , Free CPU:15152 ,Requested CPU: 1000 > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Current Used RAM: 3758096384 , Free RAM:12428838912 ,Requested RAM: 1073741824 > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) CPU STATS after allocation: for host: 1, old used: 4000, old reserved: 0, actual total: 19152, total with overprovisioning: 19152; new used:5000, reserved:0; requested cpu:1000,alloc_from_last:false > 2013-06-03 13:28:27,522 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) RAM STATS after allocation: for host: 1, old used: 3758096384, old reserved: 0, total: 16186935296; new used: 4831838208, reserved: 0; requested mem: 1073741824,alloc_from_last:false > 2013-06-03 13:28:27,539 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) VM is being created in podId: 1 > 2013-06-03 13:28:27,543 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is acquired for network id 207 as a part of network implement > 2013-06-03 13:28:27,543 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking ExternalGuestNetworkGuru to implement Ntwk[207|Guest|15] > 2013-06-03 13:28:27,576 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to implemenet Ntwk[207|Guest|15] > 2013-06-03 13:28:27,579 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-17:job-17) Deploying Virtual Router in VPC [VPC [1-VPC] > 2013-06-03 13:28:27,594 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Adding vm VM[DomainRouter|r-5-VM] to network Ntwk[207|Guest|15]; requested nic profile null > 2013-06-03 13:28:27,607 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Allocating nic for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] with requested profile null > 2013-06-03 13:28:27,648 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:27,651 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Nic is allocated successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:27,653 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is acquired for network id 207 as a part of network implement > 2013-06-03 13:28:27,653 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Network id=207 is already implemented > 2013-06-03 13:28:27,654 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is released for network id 207 as a part of network implement > 2013-06-03 13:28:27,669 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:27,694 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking JuniperSRX to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,694 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Netscaler to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,694 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking F5BigIP to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoNexus1000vVSM to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoVNMC to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking NiciraNvp to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [network.element.NiciraNvpElement] (Job-Executor-17:job-17) Checking if NiciraNvpElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking MidoNetElement to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [network.element.MidoNetElement] (Job-Executor-17:job-17) prepare called with network: Ntwk[207|Guest|15] nic: NicProfile[19-5-null-10.1.3.4-vlan://726 vm: VM[DomainRouter|r-5-VM] > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking BigSwitchVnsElement to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-17:job-17) Checking if BigSwitchVnsElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VirtualRouter to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,695 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Ovs to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,696 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking SecurityGroupProvider to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,696 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,697 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to prepare for Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:27,700 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:27,700 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Nic is prepared successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:27,711 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Plugging nic for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:27,716 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930037: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","vmType":"DomainRouter","wait":0}}] } > 2013-06-03 13:28:27,717 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930037: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","vmType":"DomainRouter","wait":0}}] } > 2013-06-03 13:28:27,717 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-117:null) Seq 1-7930037: Executing request > 2013-06-03 13:28:27,918 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Lowest available Vif device number: 4 for VM: r-5-VM > 2013-06-03 13:28:27,918 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Creating VIF for r-5-VM on nic [Nic:Guest-10.1.3.4-vlan://726] > 2013-06-03 13:28:27,954 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Couldn't find vlan network with the new name so trying old name: VLAN726 > 2013-06-03 13:28:27,961 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Creating VLAN network for 726 on host 10.102.192.17 > 2013-06-03 13:28:28,029 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Creating VLAN 726 on host 10.102.192.17 on device eth0 > 2013-06-03 13:28:28,482 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) VLAN is created for 726. The uuid is 0e933f05-e46a-4a4b-a1a6-a816dbb78925 > 2013-06-03 13:28:28,532 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-117:null) Created a vif ef894ba6-0a60-4b78-efe6-79fcb1a4c0e6 on 4 > 2013-06-03 13:28:29,413 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-117:null) Seq 1-7930037: Response Received: > 2013-06-03 13:28:29,414 DEBUG [agent.transport.Request] (DirectAgent-117:null) Seq 1-7930037: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"PlugNicAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:29,414 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930037: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { PlugNicAnswer } } > 2013-06-03 13:28:29,414 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Nic is plugged successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15]. Vm is a part of network now > 2013-06-03 13:28:29,416 DEBUG [agent.manager.AgentAttache] (DirectAgent-117:null) Seq 1-7930037: No more commands found > 2013-06-03 13:28:29,439 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:29,458 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930038: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","defaultDns1":"10.103.128.15","isRedundant":false,"add":true,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"726","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:29,459 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930038: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","defaultDns1":"10.103.128.15","isRedundant":false,"add":true,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"726","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:29,459 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-118:null) Seq 1-7930038: Executing request > 2013-06-03 13:28:30,263 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246115955 > 2013-06-03 13:28:30,292 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246115955 > 2013-06-03 13:28:30,986 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM > 2013-06-03 13:28:31,247 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy > 2013-06-03 13:28:33,273 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246118957 > 2013-06-03 13:28:33,294 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246118957 > 2013-06-03 13:28:33,724 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 4 routers to update status. > 2013-06-03 13:28:33,726 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 4 running routers. > 2013-06-03 13:28:33,735 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. > 2013-06-03 13:28:33,739 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-42:null) Seq 1-7930039: Executing request > 2013-06-03 13:28:33,800 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 4 running routers. > 2013-06-03 13:28:33,802 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 4 routers to update status. > 2013-06-03 13:28:33,814 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. > 2013-06-03 13:28:33,823 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-119:null) Seq 1-7930040: Executing request > 2013-06-03 13:28:34,263 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-42:null) Seq 1-7930039: Response Received: > 2013-06-03 13:28:34,264 DEBUG [agent.transport.Request] (DirectAgent-42:null) Seq 1-7930039: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] } > 2013-06-03 13:28:34,264 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930039: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:34,264 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: > 2013-06-03 13:28:34,264 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:34,278 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-44:null) Seq 1-7930041: Executing request > 2013-06-03 13:28:34,383 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-119:null) Seq 1-7930040: Response Received: > 2013-06-03 13:28:34,383 DEBUG [agent.transport.Request] (DirectAgent-119:null) Seq 1-7930040: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"","wait":0}}] } > 2013-06-03 13:28:34,383 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930040: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:34,383 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: > 2013-06-03 13:28:34,383 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:34,398 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:null) Seq 1-7930042: Executing request > 2013-06-03 13:28:34,413 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) External devices stats collector is running... > 2013-06-03 13:28:34,417 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-06-03 07:58:34 GMT > 2013-06-03 13:28:34,419 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-06-03 07:58:34 GMT > 2013-06-03 13:28:34,432 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 204 is not configured for external networking, so skipping usage check. > 2013-06-03 13:28:34,434 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 205 is not configured for external networking, so skipping usage check. > 2013-06-03 13:28:34,435 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 206 is not configured for external networking, so skipping usage check. > 2013-06-03 13:28:34,440 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) Network 207 is not configured for external networking, so skipping usage check. > 2013-06-03 13:28:36,268 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246121957 > 2013-06-03 13:28:36,289 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246121957 > 2013-06-03 13:28:36,923 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-118:null) Seq 1-7930038: Response Received: > 2013-06-03 13:28:36,924 DEBUG [agent.transport.Request] (DirectAgent-118:null) Seq 1-7930038: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:36,924 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930038: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } } > 2013-06-03 13:28:36,924 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-17:job-17) Succesfully added router VM[DomainRouter|r-5-VM] to guest network Ntwk[207|Guest|15] > 2013-06-03 13:28:36,924 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-17:job-17) Successfully added VPC router VM[DomainRouter|r-5-VM] to guest network Ntwk[207|Guest|15] > 2013-06-03 13:28:36,927 DEBUG [agent.manager.AgentAttache] (DirectAgent-118:null) Seq 1-7930038: No more commands found > 2013-06-03 13:28:36,928 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to implemenet Ntwk[207|Guest|15] > 2013-06-03 13:28:36,931 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Reprogramming network Ntwk[207|Guest|15] as a part of network implement > 2013-06-03 13:28:36,936 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no static nat to apply for network id=207 > 2013-06-03 13:28:36,937 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no firewall rules to apply > 2013-06-03 13:28:36,938 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no firewall rules to apply > 2013-06-03 13:28:36,940 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no port forwarding rules to apply for network id=207 > 2013-06-03 13:28:36,941 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no static nat rules to apply for network id=207 > 2013-06-03 13:28:36,942 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Applying load balancer rules of scheme Public in network id=207 > 2013-06-03 13:28:36,943 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:36,944 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Applying load balancer rules of scheme Internal in network id=207 > 2013-06-03 13:28:36,944 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:36,951 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Unable to find NetworkACL service provider for network: 207 > 2013-06-03 13:28:36,951 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to reapply network ACLs as a part of of network id=207 restart > 2013-06-03 13:28:36,951 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to re-program the network as a part of network Ntwk[207|Guest|15] implement > 2013-06-03 13:28:36,951 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Cleaning up because we're unable to implement the network Ntwk[207|Guest|15] > 2013-06-03 13:28:36,963 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 port forwarding rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:36,963 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:36,965 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 static nat rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:36,965 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:36,966 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Revoking 0 Public load balancing rules for network id=207 > 2013-06-03 13:28:36,966 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:36,967 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Revoking 0 Internal load balancing rules for network id=207 > 2013-06-03 13:28:36,968 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:36,969 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 firewall ingress rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:36,969 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:36,970 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 firewall egress rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:36,970 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:36,971 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing Network ACL Items for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:36,974 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Releasing 2 Network ACL Items for network id=207 > 2013-06-03 13:28:36,982 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Unable to find NetworkACL service provider for network: 207 > 2013-06-03 13:28:36,982 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to cleanup network ACLs as a part of shutdownNetworkRules > 2013-06-03 13:28:36,984 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) Found 0 static nat rules to apply for network id 207 > 2013-06-03 13:28:36,988 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to cleanup network id=207 resources as a part of shutdownNetwork > 2013-06-03 13:28:36,992 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Sending network shutdown to VpcVirtualRouter > 2013-06-03 13:28:37,008 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-44:null) Seq 1-7930041: Response Received: > 2013-06-03 13:28:37,008 DEBUG [agent.transport.Request] (DirectAgent-44:null) Seq 1-7930041: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:37,008 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930041: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:37,008 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:37,009 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:37,022 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:37,038 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-121:null) Seq 1-7930043: Executing request > 2013-06-03 13:28:37,056 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:37,075 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930044: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","isRedundant":false,"add":false,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"726","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:37,076 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930044: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","isRedundant":false,"add":false,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"726","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:37,076 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-122:null) Seq 1-7930044: Executing request > 2013-06-03 13:28:37,163 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-120:null) Seq 1-7930042: Response Received: > 2013-06-03 13:28:37,163 DEBUG [agent.transport.Request] (DirectAgent-120:null) Seq 1-7930042: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:37,163 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930042: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:37,163 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:37,164 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:37,180 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-14:null) Seq 1-7930045: Executing request > 2013-06-03 13:28:37,648 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-121:null) Seq 1-7930043: Response Received: > 2013-06-03 13:28:37,648 DEBUG [agent.transport.Request] (DirectAgent-121:null) Seq 1-7930043: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:37,648 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930043: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:37,649 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:37,649 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:37,664 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-123:null) Seq 1-7930046: Executing request > 2013-06-03 13:28:39,268 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246124957 > 2013-06-03 13:28:39,289 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246124957 > 2013-06-03 13:28:42,270 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246127958 > 2013-06-03 13:28:42,290 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246127958 > 2013-06-03 13:28:42,502 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-122:null) Seq 1-7930044: Response Received: > 2013-06-03 13:28:42,502 DEBUG [agent.transport.Request] (DirectAgent-122:null) Seq 1-7930044: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:42,502 DEBUG [agent.manager.AgentAttache] (DirectAgent-122:null) Seq 1-7930044: No more commands found > 2013-06-03 13:28:42,503 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930044: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } } > 2013-06-03 13:28:42,529 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:42,533 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Un-plugging nic for vm VM[DomainRouter|r-5-VM] from network Ntwk[207|Guest|15] > 2013-06-03 13:28:42,538 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930047: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","wait":0}}] } > 2013-06-03 13:28:42,539 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930047: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"55db5172-85b3-48ce-ba1e-69f79686e9c7","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:2f:c1:00:02","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://726","isolationUri":"vlan://726","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","wait":0}}] } > 2013-06-03 13:28:42,539 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-45:null) Seq 1-7930047: Executing request > 2013-06-03 13:28:42,640 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-14:null) Seq 1-7930045: Response Received: > 2013-06-03 13:28:42,640 DEBUG [agent.transport.Request] (DirectAgent-14:null) Seq 1-7930045: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:42,640 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930045: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:42,641 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:42,641 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:42,669 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-124:null) Seq 1-7930048: Executing request > 2013-06-03 13:28:42,709 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-123:null) Seq 1-7930046: Response Received: > 2013-06-03 13:28:42,709 DEBUG [agent.transport.Request] (DirectAgent-123:null) Seq 1-7930046: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:42,709 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930046: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:42,710 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:42,710 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:43,215 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-124:null) Seq 1-7930048: Response Received: > 2013-06-03 13:28:43,215 DEBUG [agent.transport.Request] (DirectAgent-124:null) Seq 1-7930048: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, [{"NetworkUsageAnswer":{"routerName":"r-5-VM","bytesSent":0,"bytesReceived":0,"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:43,216 DEBUG [agent.transport.Request] (RouterMonitor-1:null) Seq 1-7930048: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 10, { NetworkUsageAnswer } } > 2013-06-03 13:28:43,216 DEBUG [agent.manager.AgentManagerImpl] (RouterMonitor-1:null) Details from executing class com.cloud.agent.api.NetworkUsageCommand: success > 2013-06-03 13:28:43,216 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Recieved and Sent bytes are both 0. Not updating user_statistics > 2013-06-03 13:28:43,875 INFO [xen.resource.XenServer56Resource] (DirectAgent-45:null) Catch com.xensource.xenapi.Types$InternalError: failed to destory VLAN eth0 on host 618048f8-1665-4cb2-883d-c47e4a7fb33d due to The server failed to handle your request, due to an internal error. The given message may give details useful for debugging the problem. > 2013-06-03 13:28:43,875 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-45:null) Seq 1-7930047: Response Received: > 2013-06-03 13:28:43,877 DEBUG [agent.transport.Request] (DirectAgent-45:null) Seq 1-7930047: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"UnPlugNicAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:43,877 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930047: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { UnPlugNicAnswer } } > 2013-06-03 13:28:43,877 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Nic is unplugged successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:43,881 DEBUG [agent.manager.AgentAttache] (DirectAgent-45:null) Seq 1-7930047: No more commands found > 2013-06-03 13:28:43,884 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking JuniperSRX to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Netscaler to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking F5BigIP to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoNexus1000vVSM to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoVNMC to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking NiciraNvp to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,894 DEBUG [network.element.NiciraNvpElement] (Job-Executor-17:job-17) Checking if NiciraNvpElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:43,894 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking MidoNetElement to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [network.element.MidoNetElement] (Job-Executor-17:job-17) release called with network: Ntwk[207|Guest|15] nic: NicProfile[19-5-null-10.1.3.4-null vm: VM[DomainRouter|r-5-VM] > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking BigSwitchVnsElement to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-17:job-17) Checking if BigSwitchVnsElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VirtualRouter to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Ovs to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking SecurityGroupProvider to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to release Nic[19-5-null-10.1.3.4] > 2013-06-03 13:28:43,895 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully released nic Nic[19-5-null-10.1.3.4]for vm VM[DomainRouter|r-5-VM] > 2013-06-03 13:28:43,902 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:43,917 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Removed nic id=19 > 2013-06-03 13:28:43,919 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Revoving nic secondary ip entry ... > 2013-06-03 13:28:43,924 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-17:job-17) Successfully unplugged nic in network Ntwk[207|Guest|15] for virtual router VM[DomainRouter|r-5-VM] > 2013-06-03 13:28:43,927 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Sending network shutdown to InternalLbVm > 2013-06-03 13:28:43,928 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Network id=207 is shutdown successfully, cleaning up corresponding resources now. > 2013-06-03 13:28:43,931 DEBUG [network.guru.GuestNetworkGuru] (Job-Executor-17:job-17) Releasing vnet for the network id=207 > 2013-06-03 13:28:43,954 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is released for network id 207 as a part of network implement > 2013-06-03 13:28:43,954 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Unable to contact resource. > com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to apply network rules as a part of network Ntwk[207|Guest|15] implement > at com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(NetworkManagerImpl.java:1949) > at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java:1841) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2018) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:239) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3340) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2867) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2853) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) > 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) > 2013-06-03 13:28:43,958 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Cleaning up resources for the vm VM[User|v1tier3] in Starting state > 2013-06-03 13:28:43,961 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930049: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}] } > 2013-06-03 13:28:43,961 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930049: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}] } > 2013-06-03 13:28:43,961 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-125:null) Seq 1-7930049: Executing request > 2013-06-03 13:28:44,071 INFO [xen.resource.CitrixResourceBase] (DirectAgent-125:null) VM does not exist on XenServer618048f8-1665-4cb2-883d-c47e4a7fb33d > 2013-06-03 13:28:44,071 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-125:null) Seq 1-7930049: Response Received: > 2013-06-03 13:28:44,072 DEBUG [agent.transport.Request] (DirectAgent-125:null) Seq 1-7930049: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] } > 2013-06-03 13:28:44,072 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930049: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { StopAnswer } } > 2013-06-03 13:28:44,077 DEBUG [agent.manager.AgentAttache] (DirectAgent-125:null) Seq 1-7930049: No more commands found > 2013-06-03 13:28:44,088 DEBUG [db.Transaction.Transaction] (Job-Executor-17:job-17) Rolling back the transaction: Time = 9 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:2181-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.cleanup:1058-VirtualMachineManagerImpl.advanceStart:946-VirtualMachineManagerImpl.start:550-VMEntityManagerImpl.deployVirtualMachine:239-VirtualMachineEntityImpl.deploy:209 > 2013-06-03 13:28:44,089 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully released network resources for the vm VM[User|v1tier3] > 2013-06-03 13:28:44,089 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully cleanued up resources for the vm VM[User|v1tier3] in Starting state > 2013-06-03 13:28:44,103 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: [1] > 2013-06-03 13:28:44,103 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning. > 2013-06-03 13:28:44,126 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) 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 > 2013-06-03 13:28:44,134 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total CPU: 19152 and CPU after applying overprovisioning: 19152 > 2013-06-03 13:28:44,134 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total RAM: 16186935744 and RAM after applying overprovisioning: 16186935296 > 2013-06-03 13:28:44,134 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) release cpu from host: 1, old used: 5000,reserved: 0, actual total: 19152, total with overprovisioning: 19152; new used: 4000,reserved:0; movedfromreserved: false,moveToReserveredfalse > 2013-06-03 13:28:44,135 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) release mem from host: 1, old used: 4831838208,reserved: 0, total: 16186935296; new used: 3758096384,reserved:0; movedfromreserved: false,moveToReserveredfalse > 2013-06-03 13:28:44,170 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null > 2013-06-03 13:28:44,170 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully transitioned to start state for VM[User|v1tier3] reservation id = 7cbc0f6c-773e-43cb-93ca-5e5c647d77f3 > 2013-06-03 13:28:44,174 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Trying to deploy VM, vm has dcId: 1 and podId: 1 > 2013-06-03 13:28:44,174 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: null > 2013-06-03 13:28:44,186 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: null > 2013-06-03 13:28:44,187 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_907b054a@78c218ac > 2013-06-03 13:28:44,187 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 1000, requested ram: 1073741824 > 2013-06-03 13:28:44,187 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Is ROOT volume READY (pool already allocated)?: No > 2013-06-03 13:28:44,187 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-17:job-17) Searching resources only under specified Pod: 1 > 2013-06-03 13:28:44,187 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-17:job-17) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under this Pod: 1 > 2013-06-03 13:28:44,196 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking resources in Cluster: 1 under Pod: 1 > 2013-06-03 13:28:44,197 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 > 2013-06-03 13:28:44,200 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] > 2013-06-03 13:28:44,204 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] > 2013-06-03 13:28:44,204 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024 > 2013-06-03 13:28:44,210 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 1000 and requested RAM: 1073741824 , cpuOverprovisioningFactor: 1.0 > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Hosts's actual total CPU: 19152 and CPU after applying overprovisioning: 19152 > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Free CPU: 15152 , Requested CPU: 1000 > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Free RAM: 12428838912 , Requested RAM: 1073741824 > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Host has enough CPU and RAM available > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 4000, reserved: 0, actual total: 19152, total with overprovisioning: 19152; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2013-06-03 13:28:44,213 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 3758096384, reserved: 0, total: 16186935296; requested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true > 2013-06-03 13:28:44,213 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1 > 2013-06-03 13:28:44,213 DEBUG [allocator.impl.FirstFitAllocator] (Job-Executor-17:job-17 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts > 2013-06-03 13:28:44,215 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking suitable pools for volume (Id, Type): (8,ROOT) > 2013-06-03 13:28:44,216 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) We need to allocate new storagepool for this volume > 2013-06-03 13:28:44,216 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Calling StoragePoolAllocators to find suitable pools > 2013-06-03 13:28:44,285 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-17:job-17) Checking pool: 1 for volume allocation [Vol[8|vm=8|ROOT]], maxSize : 1759218630656, totalAllocatedSize : 76673156096, askingSize : 21474836480, allocated disable threshold: 0.85 > 2013-06-03 13:28:44,286 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM > 2013-06-03 13:28:44,286 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Checking if host: 1 can access any suitable storage pool for volume: ROOT > 2013-06-03 13:28:44,287 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Host: 1 can access pool: 1 > 2013-06-03 13:28:44,289 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Found a potential host id: 1 name: xen61-band17 and associated storage pools for this VM > 2013-06-03 13:28:44,294 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(1))] > 2013-06-03 13:28:44,294 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Deployment found - P0=VM[User|v1tier3], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(8|ROOT-->Pool(1))] > 2013-06-03 13:28:44,310 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null > 2013-06-03 13:28:44,327 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total CPU: 19152 and CPU after applying overprovisioning: 19152 > 2013-06-03 13:28:44,327 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) We are allocating VM, increasing the used capacity of this host:1 > 2013-06-03 13:28:44,327 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Current Used CPU: 4000 , Free CPU:15152 ,Requested CPU: 1000 > 2013-06-03 13:28:44,328 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Current Used RAM: 3758096384 , Free RAM:12428838912 ,Requested RAM: 1073741824 > 2013-06-03 13:28:44,328 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) CPU STATS after allocation: for host: 1, old used: 4000, old reserved: 0, actual total: 19152, total with overprovisioning: 19152; new used:5000, reserved:0; requested cpu:1000,alloc_from_last:false > 2013-06-03 13:28:44,328 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) RAM STATS after allocation: for host: 1, old used: 3758096384, old reserved: 0, total: 16186935296; new used: 4831838208, reserved: 0; requested mem: 1073741824,alloc_from_last:false > 2013-06-03 13:28:44,335 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) VM is being created in podId: 1 > 2013-06-03 13:28:44,339 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is acquired for network id 207 as a part of network implement > 2013-06-03 13:28:44,340 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking ExternalGuestNetworkGuru to implement Ntwk[207|Guest|15] > 2013-06-03 13:28:44,384 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to implemenet Ntwk[207|Guest|15] > 2013-06-03 13:28:44,387 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-17:job-17) Deploying Virtual Router in VPC [VPC [1-VPC] > 2013-06-03 13:28:44,401 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Adding vm VM[DomainRouter|r-5-VM] to network Ntwk[207|Guest|15]; requested nic profile null > 2013-06-03 13:28:44,411 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Allocating nic for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] with requested profile null > 2013-06-03 13:28:44,441 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:44,444 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Nic is allocated successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:44,447 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is acquired for network id 207 as a part of network implement > 2013-06-03 13:28:44,447 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Network id=207 is already implemented > 2013-06-03 13:28:44,447 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is released for network id 207 as a part of network implement > 2013-06-03 13:28:44,462 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking JuniperSRX to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Netscaler to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking F5BigIP to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoNexus1000vVSM to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoVNMC to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking NiciraNvp to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [network.element.NiciraNvpElement] (Job-Executor-17:job-17) Checking if NiciraNvpElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:44,472 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking MidoNetElement to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,472 DEBUG [network.element.MidoNetElement] (Job-Executor-17:job-17) prepare called with network: Ntwk[207|Guest|15] nic: NicProfile[20-5-null-10.1.3.4-vlan://722 vm: VM[DomainRouter|r-5-VM] > 2013-06-03 13:28:44,473 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking BigSwitchVnsElement to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,473 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-17:job-17) Checking if BigSwitchVnsElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:28:44,473 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VirtualRouter to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,473 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Ovs to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,473 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking SecurityGroupProvider to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,473 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,475 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to prepare for Nic[20-5-null-10.1.3.4] > 2013-06-03 13:28:44,477 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:44,477 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Nic is prepared successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:44,488 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Plugging nic for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:28:44,493 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930050: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","vmType":"DomainRouter","wait":0}}] } > 2013-06-03 13:28:44,494 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930050: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","vmType":"DomainRouter","wait":0}}] } > 2013-06-03 13:28:44,494 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-126:null) Seq 1-7930050: Executing request > 2013-06-03 13:28:44,690 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Lowest available Vif device number: 4 for VM: r-5-VM > 2013-06-03 13:28:44,690 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Creating VIF for r-5-VM on nic [Nic:Guest-10.1.3.4-vlan://722] > 2013-06-03 13:28:44,729 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Couldn't find vlan network with the new name so trying old name: VLAN722 > 2013-06-03 13:28:44,736 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Creating VLAN network for 722 on host 10.102.192.17 > 2013-06-03 13:28:44,786 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Creating VLAN 722 on host 10.102.192.17 on device eth0 > 2013-06-03 13:28:45,237 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) VLAN is created for 722. The uuid is d6f5473a-fcb6-47b8-85ca-f6ded041ecda > 2013-06-03 13:28:45,278 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246130989 > 2013-06-03 13:28:45,284 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-126:null) Created a vif ac82e347-92c1-7fd7-4ffb-b9c7390bfcb2 on 4 > 2013-06-03 13:28:45,308 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246130989 > 2013-06-03 13:28:46,162 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-126:null) Seq 1-7930050: Response Received: > 2013-06-03 13:28:46,163 DEBUG [agent.transport.Request] (DirectAgent-126:null) Seq 1-7930050: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"PlugNicAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:46,163 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930050: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { PlugNicAnswer } } > 2013-06-03 13:28:46,163 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Nic is plugged successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15]. Vm is a part of network now > 2013-06-03 13:28:46,165 DEBUG [agent.manager.AgentAttache] (DirectAgent-126:null) Seq 1-7930050: No more commands found > 2013-06-03 13:28:46,187 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:46,220 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930051: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","defaultDns1":"10.103.128.15","isRedundant":false,"add":true,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"722","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:46,221 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930051: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","defaultDns1":"10.103.128.15","isRedundant":false,"add":true,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"722","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:46,222 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-46:null) Seq 1-7930051: Executing request > 2013-06-03 13:28:48,268 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246133989 > 2013-06-03 13:28:48,297 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246133989 > 2013-06-03 13:28:51,285 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246136988 > 2013-06-03 13:28:51,300 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246136988 > 2013-06-03 13:28:53,610 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-46:null) Seq 1-7930051: Response Received: > 2013-06-03 13:28:53,611 DEBUG [agent.transport.Request] (DirectAgent-46:null) Seq 1-7930051: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:53,611 DEBUG [agent.manager.AgentAttache] (DirectAgent-46:null) Seq 1-7930051: No more commands found > 2013-06-03 13:28:53,611 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930051: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } } > 2013-06-03 13:28:53,611 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-17:job-17) Succesfully added router VM[DomainRouter|r-5-VM] to guest network Ntwk[207|Guest|15] > 2013-06-03 13:28:53,611 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-17:job-17) Successfully added VPC router VM[DomainRouter|r-5-VM] to guest network Ntwk[207|Guest|15] > 2013-06-03 13:28:53,615 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to implemenet Ntwk[207|Guest|15] > 2013-06-03 13:28:53,618 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Reprogramming network Ntwk[207|Guest|15] as a part of network implement > 2013-06-03 13:28:53,623 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no static nat to apply for network id=207 > 2013-06-03 13:28:53,624 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no firewall rules to apply > 2013-06-03 13:28:53,626 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no firewall rules to apply > 2013-06-03 13:28:53,627 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no port forwarding rules to apply for network id=207 > 2013-06-03 13:28:53,628 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) There are no static nat rules to apply for network id=207 > 2013-06-03 13:28:53,630 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Applying load balancer rules of scheme Public in network id=207 > 2013-06-03 13:28:53,630 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:53,631 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Applying load balancer rules of scheme Internal in network id=207 > 2013-06-03 13:28:53,631 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:53,638 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Unable to find NetworkACL service provider for network: 207 > 2013-06-03 13:28:53,638 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to reapply network ACLs as a part of of network id=207 restart > 2013-06-03 13:28:53,638 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to re-program the network as a part of network Ntwk[207|Guest|15] implement > 2013-06-03 13:28:53,639 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Cleaning up because we're unable to implement the network Ntwk[207|Guest|15] > 2013-06-03 13:28:53,650 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 port forwarding rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:53,650 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:53,651 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 static nat rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:53,651 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:53,652 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Revoking 0 Public load balancing rules for network id=207 > 2013-06-03 13:28:53,653 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:53,654 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) Revoking 0 Internal load balancing rules for network id=207 > 2013-06-03 13:28:53,654 DEBUG [network.lb.LoadBalancingRulesManagerImpl] (Job-Executor-17:job-17) There are no Load Balancing Rules to forward to the network elements > 2013-06-03 13:28:53,655 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 firewall ingress rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:53,655 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:53,657 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing 0 firewall egress rules for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:53,657 DEBUG [network.firewall.FirewallManagerImpl] (Job-Executor-17:job-17) There are no rules to forward to the network elements > 2013-06-03 13:28:53,657 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Releasing Network ACL Items for network id=207 as a part of shutdownNetworkRules > 2013-06-03 13:28:53,660 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Releasing 2 Network ACL Items for network id=207 > 2013-06-03 13:28:53,663 DEBUG [network.vpc.NetworkACLManagerImpl] (Job-Executor-17:job-17) Unable to find NetworkACL service provider for network: 207 > 2013-06-03 13:28:53,663 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to cleanup network ACLs as a part of shutdownNetworkRules > 2013-06-03 13:28:53,664 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-17:job-17) Found 0 static nat rules to apply for network id 207 > 2013-06-03 13:28:53,668 WARN [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Failed to cleanup network id=207 resources as a part of shutdownNetwork > 2013-06-03 13:28:53,672 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Sending network shutdown to VpcVirtualRouter > 2013-06-03 13:28:53,693 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:53,737 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:53,782 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930052: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","isRedundant":false,"add":false,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"722","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:53,785 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930052: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"10.1.3.1","networkDomain":"cs2cloud.internal","isRedundant":false,"add":false,"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"accessDetails":{"router.guest.ip":"10.1.3.4","guest.vlan.tag":"722","guest.network.gateway":"10.1.3.4","guest.bridge":"10.1.3.255","router.name":"r-5-VM","router.ip":"169.254.0.186"},"wait":0}}] } > 2013-06-03 13:28:53,788 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-5:null) Seq 1-7930052: Executing request > 2013-06-03 13:28:53,965 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running... > 2013-06-03 13:28:54,036 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 4-546897989: Received: { Ans: , MgmtId: 90310994128556, via: 4, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } > 2013-06-03 13:28:54,269 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246139988 > 2013-06-03 13:28:54,288 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246139988 > 2013-06-03 13:28:57,264 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246142987 > 2013-06-03 13:28:57,285 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246142987 > 2013-06-03 13:28:59,113 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-5:null) Seq 1-7930052: Response Received: > 2013-06-03 13:28:59,114 DEBUG [agent.transport.Request] (DirectAgent-5:null) Seq 1-7930052: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:28:59,114 DEBUG [agent.manager.AgentAttache] (DirectAgent-5:null) Seq 1-7930052: No more commands found > 2013-06-03 13:28:59,114 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930052: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } } > 2013-06-03 13:28:59,140 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:28:59,144 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Un-plugging nic for vm VM[DomainRouter|r-5-VM] from network Ntwk[207|Guest|15] > 2013-06-03 13:28:59,149 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930053: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","wait":0}}] } > 2013-06-03 13:28:59,149 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930053: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":4,"networkRateMbps":200,"defaultNic":false,"uuid":"0d23c2c4-64d4-4da3-947c-c8dbc8ce6234","ip":"10.1.3.4","netmask":"255.255.255.0","gateway":"10.1.3.4","mac":"02:00:10:a1:00:03","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://722","isolationUri":"vlan://722","isSecurityGroupEnabled":false},"instanceName":"r-5-VM","wait":0}}] } > 2013-06-03 13:28:59,150 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-127:null) Seq 1-7930053: Executing request > 2013-06-03 13:29:00,270 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246145991 > 2013-06-03 13:29:00,307 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246145991 > 2013-06-03 13:29:00,408 INFO [xen.resource.XenServer56Resource] (DirectAgent-127:null) Catch com.xensource.xenapi.Types$InternalError: failed to destory VLAN eth0 on host 618048f8-1665-4cb2-883d-c47e4a7fb33d due to The server failed to handle your request, due to an internal error. The given message may give details useful for debugging the problem. > 2013-06-03 13:29:00,409 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-127:null) Seq 1-7930053: Response Received: > 2013-06-03 13:29:00,413 DEBUG [agent.transport.Request] (DirectAgent-127:null) Seq 1-7930053: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"UnPlugNicAnswer":{"result":true,"details":"success","wait":0}}] } > 2013-06-03 13:29:00,413 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930053: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { UnPlugNicAnswer } } > 2013-06-03 13:29:00,413 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Nic is unplugged successfully for vm VM[DomainRouter|r-5-VM] in network Ntwk[207|Guest|15] > 2013-06-03 13:29:00,417 DEBUG [agent.manager.AgentAttache] (DirectAgent-127:null) Seq 1-7930053: No more commands found > 2013-06-03 13:29:00,419 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking JuniperSRX to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Netscaler to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking F5BigIP to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoNexus1000vVSM to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking CiscoVNMC to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking NiciraNvp to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [network.element.NiciraNvpElement] (Job-Executor-17:job-17) Checking if NiciraNvpElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:29:00,428 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking MidoNetElement to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,428 DEBUG [network.element.MidoNetElement] (Job-Executor-17:job-17) release called with network: Ntwk[207|Guest|15] nic: NicProfile[20-5-null-10.1.3.4-null vm: VM[DomainRouter|r-5-VM] > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking BigSwitchVnsElement to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [network.element.BigSwitchVnsElement] (Job-Executor-17:job-17) Checking if BigSwitchVnsElement can handle service Connectivity on network TIER-3 InternalLBwithNoNetworkACL > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VirtualRouter to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking Ovs to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking SecurityGroupProvider to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking VpcVirtualRouter to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Asking InternalLbVm to release Nic[20-5-null-10.1.3.4] > 2013-06-03 13:29:00,429 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully released nic Nic[20-5-null-10.1.3.4]for vm VM[DomainRouter|r-5-VM] > 2013-06-03 13:29:00,441 DEBUG [cloud.network.NetworkModelImpl] (Job-Executor-17:job-17) Service SecurityGroup is not supported in the network id=207 > 2013-06-03 13:29:00,450 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Removed nic id=20 > 2013-06-03 13:29:00,451 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Revoving nic secondary ip entry ... > 2013-06-03 13:29:00,456 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-17:job-17) Successfully unplugged nic in network Ntwk[207|Guest|15] for virtual router VM[DomainRouter|r-5-VM] > 2013-06-03 13:29:00,459 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Sending network shutdown to InternalLbVm > 2013-06-03 13:29:00,460 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Network id=207 is shutdown successfully, cleaning up corresponding resources now. > 2013-06-03 13:29:00,463 DEBUG [network.guru.GuestNetworkGuru] (Job-Executor-17:job-17) Releasing vnet for the network id=207 > 2013-06-03 13:29:00,489 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-17:job-17) Lock is released for network id 207 as a part of network implement > 2013-06-03 13:29:00,489 INFO [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Unable to contact resource. > com.cloud.exception.ResourceUnavailableException: Resource [DataCenter:1] is unreachable: Unable to apply network rules as a part of network Ntwk[207|Guest|15] implement > at com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(NetworkManagerImpl.java:1949) > at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java:1841) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2018) > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:842) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3340) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2867) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2853) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) > 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) > 2013-06-03 13:29:00,497 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Cleaning up resources for the vm VM[User|v1tier3] in Starting state > 2013-06-03 13:29:00,499 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930054: Sending { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}] } > 2013-06-03 13:29:00,499 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930054: Executing: { Cmd , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-8-VM","wait":0}}] } > 2013-06-03 13:29:00,499 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-128:null) Seq 1-7930054: Executing request > 2013-06-03 13:29:00,610 INFO [xen.resource.CitrixResourceBase] (DirectAgent-128:null) VM does not exist on XenServer618048f8-1665-4cb2-883d-c47e4a7fb33d > 2013-06-03 13:29:00,610 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-128:null) Seq 1-7930054: Response Received: > 2013-06-03 13:29:00,610 DEBUG [agent.transport.Request] (DirectAgent-128:null) Seq 1-7930054: Processing: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] } > 2013-06-03 13:29:00,610 DEBUG [agent.transport.Request] (Job-Executor-17:job-17) Seq 1-7930054: Received: { Ans: , MgmtId: 90310994128556, via: 1, Ver: v1, Flags: 110, { StopAnswer } } > 2013-06-03 13:29:00,615 DEBUG [agent.manager.AgentAttache] (DirectAgent-128:null) Seq 1-7930054: No more commands found > 2013-06-03 13:29:00,619 DEBUG [db.Transaction.Transaction] (Job-Executor-17:job-17) Rolling back the transaction: Time = 2 Name = -AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679; called by -Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.interceptComplete:56-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-NetworkManagerImpl.release:2181-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-VirtualMachineManagerImpl.cleanup:1058-VirtualMachineManagerImpl.advanceStart:946-VirtualMachineManagerImpl.start:550-VMEntityManagerImpl.deployVirtualMachine:243-VirtualMachineEntityImpl.deploy:209 > 2013-06-03 13:29:00,619 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully released network resources for the vm VM[User|v1tier3] > 2013-06-03 13:29:00,620 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-17:job-17) Successfully cleanued up resources for the vm VM[User|v1tier3] in Starting state > 2013-06-03 13:29:00,631 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) Deploy avoids pods: null, clusters: null, hosts: [1] > 2013-06-03 13:29:00,631 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl] (Job-Executor-17:job-17) DataCenter id = '1' provided is in avoid set, DeploymentPlanner cannot allocate the VM, returning. > 2013-06-03 13:29:00,655 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) 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 > 2013-06-03 13:29:00,662 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total CPU: 19152 and CPU after applying overprovisioning: 19152 > 2013-06-03 13:29:00,662 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) Hosts's actual total RAM: 16186935744 and RAM after applying overprovisioning: 16186935296 > 2013-06-03 13:29:00,662 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) release cpu from host: 1, old used: 5000,reserved: 0, actual total: 19152, total with overprovisioning: 19152; new used: 4000,reserved:0; movedfromreserved: false,moveToReserveredfalse > 2013-06-03 13:29:00,662 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) release mem from host: 1, old used: 4831838208,reserved: 0, total: 16186935296; new used: 3758096384,reserved:0; movedfromreserved: false,moveToReserveredfalse > 2013-06-03 13:29:00,696 DEBUG [cloud.vm.UserVmManagerImpl] (Job-Executor-17:job-17) Destroying vm VM[User|v1tier3] as it failed to create on Host with Id:null > 2013-06-03 13:29:00,731 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-17:job-17) VM state transitted from :Stopped to Error with event: OperationFailedToErrorvm's original host id: null new host id: null host id before state transition: null > 2013-06-03 13:29:00,743 WARN [apache.cloudstack.alerts] (Job-Executor-17:job-17) alertType:: 8 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Failed to deploy Vm with Id: 8, on Host with Id: null > 2013-06-03 13:29:00,795 INFO [user.vm.DeployVMCmd] (Job-Executor-17:job-17) com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|v1tier3]Scope=interface com.cloud.dc.DataCenter; id=1 > 2013-06-03 13:29:00,795 INFO [user.vm.DeployVMCmd] (Job-Executor-17:job-17) Unable to create a deployment for VM[User|v1tier3] > com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|v1tier3]Scope=interface com.cloud.dc.DataCenter; id=1 > at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:813) > at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550) > at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:243) > at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:209) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:3340) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2867) > at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2853) > at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:420) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155) > at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) > 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) > 2013-06-03 13:29:00,796 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-17:job-17) Complete async job-17, jobStatus: 2, resultCode: 530, result: Error Code: 533 Error text: Unable to create a deployment for VM[User|v1tier3] > 2013-06-03 13:29:00,986 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM > 2013-06-03 13:29:01,248 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy > 2013-06-03 13:29:03,268 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===START=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246148989 > 2013-06-03 13:29:03,281 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-20:null) Async job-17 completed > 2013-06-03 13:29:03,287 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null) ===END=== 10.144.7.12 -- GET command=queryAsyncJobResult&jobId=0626cd3e-6d0a-45d4-8a8e-2266cc957873&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246148989 > 2013-06-03 13:29:03,297 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===START=== 10.144.7.12 -- GET command=listVirtualMachines&id=34c90cc0-68be-4a4b-a382-2800b09585b6&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246149019 > 2013-06-03 13:29:03,319 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null) ===END=== 10.144.7.12 -- GET command=listVirtualMachines&id=34c90cc0-68be-4a4b-a382-2800b09585b6&response=json&sessionkey=hdTjwOvy%2F%2B%2FbdFij81rXC7%2F%2BaJk%3D&_=1370246149019 > 2013-06-03 13:29:03,720 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status. > 2013-06-03 13:29:03,724 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. > 2013-06-03 13:29:03,789 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 3 routers to update status. > 2013-06-03 13:29:03,793 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status. > ^C > NOTE : > =========================== > VM deployment succeeds when the VPC tier is created with a network offering having following service capabilities : dhcp: VpcVirtualRouter, Lb: InternalLbVm, SourceNat: VpcVirtualRouter, Dns: VpcVirtualRouter, NetworkACL: VpcVirtualRouter -- 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