Return-Path: X-Original-To: apmail-cloudstack-dev-archive@www.apache.org Delivered-To: apmail-cloudstack-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 6B118F475 for ; Fri, 19 Apr 2013 21:40:00 +0000 (UTC) Received: (qmail 37289 invoked by uid 500); 19 Apr 2013 21:39:59 -0000 Delivered-To: apmail-cloudstack-dev-archive@cloudstack.apache.org Received: (qmail 37243 invoked by uid 500); 19 Apr 2013 21:39:59 -0000 Mailing-List: contact dev-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 dev@cloudstack.apache.org Received: (qmail 37234 invoked by uid 99); 19 Apr 2013 21:39:59 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 19 Apr 2013 21:39:59 +0000 X-ASF-Spam-Status: No, hits=1.8 required=5.0 tests=FREEMAIL_ENVFROM_END_DIGIT,HTML_MESSAGE,NORMAL_HTTP_TO_IP,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of kurushi4000@gmail.com designates 209.85.216.173 as permitted sender) Received: from [209.85.216.173] (HELO mail-qc0-f173.google.com) (209.85.216.173) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 19 Apr 2013 21:39:41 +0000 Received: by mail-qc0-f173.google.com with SMTP id b12so2289893qca.4 for ; Fri, 19 Apr 2013 14:39:20 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:x-received:date:message-id:subject:from:to :content-type; bh=fJzP55gC+Ia8UPOb8Tym97m3W/CWzNXaA54rmyx8OVc=; b=H+5hiZ7CawUP85r2l7tMjcfJ2VC+40wLnaWlSkzUI1MWCIpMzp28BykHIueGoR5U43 Zd0MezTBTCv4S1Q5OMugfEfvsQseW9Qv7TTw+U5iJwW1U22YYmU1UWpRxhv1yi34myBI DkhT/bSS1ZEarylQxuHzzcuktXcjBIpwUHRkS098lmbDY6XoVy4yLDIcBNT+Z2mN+QxN ghxG1LvowpUKA+er2+tS+gSrep692Zac7Y+zubXqCm5XLfZNs7ILHwJb6UM4pX/LLYh1 gWCBSwtHYQivXl05THzGT8MEZDRiCA3goQlD04CXwsf1u/sdj5iwgLRq7mxtiwk/s6Nc /JVg== MIME-Version: 1.0 X-Received: by 10.49.0.67 with SMTP id 3mr17736296qec.9.1366407560184; Fri, 19 Apr 2013 14:39:20 -0700 (PDT) Received: by 10.49.75.136 with HTTP; Fri, 19 Apr 2013 14:39:20 -0700 (PDT) Date: Fri, 19 Apr 2013 23:39:20 +0200 Message-ID: Subject: CS 4.0.0 - Bug onto xcp server 1.1 - can't launch any vm From: benoit lair To: dev@cloudstack.apache.org Content-Type: multipart/alternative; boundary=047d7b33d2143e4bfd04dabd8d69 X-Virus-Checked: Checked by ClamAV on apache.org --047d7b33d2143e4bfd04dabd8d69 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Hello guys, I'm testing an advanced zone with a cluster of an xcp server 1.1. Since last reboot, i got problems trying launch any vm onto this server. I got this error message on cs mgmt server : Resource [Host:30] is unreachable: Host 30: Unable to start instance due to null The host 30 is my xcp server onto its cluster If somebody can help me to troubleshoot why my xcp server doesn't want to launch my vms. For info i got my systems vms running onto this server (console proxy vm and ssvm vm + vpc vr vm), xe vm-list repond (so xcp-xapi is running) a restart of xapi is okay (so xapi daemon is not freezed) If somebody can help to troubleshoot this, thanks a lot. Here are the mgmt server log output : 2013-04-19 23:11:44,060 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 30-307298557: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:11:55,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:11:55,444 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:11:55,997 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-04-19 23:11:57,172 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-04-19 23:11:57,181 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-234:null) Seq 30-307298558: Executing request 2013-04-19 23:11:57,438 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-234:null) Seq 30-307298558: Response Received: 2013-04-19 23:11:57,439 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 30-307298558: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-04-19 23:12:05,358 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 33 2013-04-19 23:12:21,555 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 34 2013-04-19 23:12:25,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:12:25,442 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:12:25,820 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2013-04-19 21:12:25 GMT 2013-04-19 23:12:25,822 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2013-04-19 21:12:25 GMT 2013-04-19 23:12:25,945 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) External load balancer devices stats collector is running... 2013-04-19 23:12:25,985 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers. 2013-04-19 23:12:25,996 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-04-19 23:12:33,079 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-78:null) Ping from 30 2013-04-19 23:12:40,013 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running... 2013-04-19 23:12:42,464 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-46:null) Seq 30-307298339: Executing request 2013-04-19 23:12:42,742 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-46:null) Seq 30-307298339: Response Received: 2013-04-19 23:12:42,743 DEBUG [agent.transport.Request] (DirectAgent-46:null) Seq 30-307298339: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":4,"_newStates":{},"_isExecuted":false,"= result":true,"wait":0}}] } 2013-04-19 23:12:44,061 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running... 2013-04-19 23:12:44,122 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 33-600178738: Received: { Ans: , MgmtId: 138942225534257, via: 33, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:12:44,129 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-29:null) Seq 30-307298559: Executing request 2013-04-19 23:12:55,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:12:55,442 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:12:55,798 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ... 2013-04-19 23:12:55,798 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity 2013-04-19 23:12:55,798 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update 2013-04-19 23:12:55,813 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 3 VMs on host 30 2013-04-19 23:12:55,825 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 13 VM, not running on host 30 2013-04-19 23:12:55,831 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Calibrate reserved cpu for host: 30 old reservedCpu:500 new reservedCpu:1500 2013-04-19 23:12:55,832 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Calibrate reserved memory for host: 30 old reservedMem:536870912 new reservedMem:1610612736 2013-04-19 23:12:55,841 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update 2013-04-19 23:12:55,841 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update 2013-04-19 23:12:55,846 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-29:null) Seq 30-307298559: Response Received: 2013-04-19 23:12:55,847 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 30-307298559: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:12:55,854 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-47:null) Seq 30-307298560: Executing request 2013-04-19 23:12:55,857 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 150311272448 for capacity type - 3 , DataCenterId - 3, HostOrPoolId - 211, PodId 3 2013-04-19 23:12:55,866 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 483171237888 for capacity type - 3 , DataCenterId - 3, HostOrPoolId - 213, PodId 3 2013-04-19 23:12:55,866 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update 2013-04-19 23:12:55,866 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans 2013-04-19 23:12:55,934 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans 2013-04-19 23:12:55,935 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip 2013-04-19 23:12:55,958 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip 2013-04-19 23:12:55,958 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity 2013-04-19 23:12:55,997 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-04-19 23:12:56,024 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ... 2013-04-19 23:12:57,439 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-04-19 23:12:57,448 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-237:null) Seq 30-307298561: Executing request 2013-04-19 23:12:57,719 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-237:null) Seq 30-307298561: Response Received: 2013-04-19 23:12:57,719 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 30-307298561: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-04-19 23:13:05,357 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-1:null) Ping from 33 2013-04-19 23:13:07,642 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-47:null) Seq 30-307298560: Response Received: 2013-04-19 23:13:07,642 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 30-307298560: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:13:21,555 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-3:null) Ping from 34 2013-04-19 23:13:25,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:13:25,441 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:13:25,997 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-04-19 23:13:34,076 DEBUG [xen.resource.XenServerConnectionPool] (DirectAgent-235:null) Session is invalid for method: host.get_by_uuid due to null. Reconnecting...retry=3D1 2013-04-19 23:13:37,298 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-235:null) Ping from 30 2013-04-19 23:13:40,017 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running... 2013-04-19 23:13:42,464 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-138:null) Seq 30-307298339: Executing request 2013-04-19 23:13:42,743 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-138:null) Seq 30-307298339: Response Received: 2013-04-19 23:13:42,743 DEBUG [agent.transport.Request] (DirectAgent-138:null) Seq 30-307298339: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, [{"ClusterSyncAnswer":{"_clusterId":4,"_newStates":{},"_isExecuted":false,"= result":true,"wait":0}}] } 2013-04-19 23:13:54,680 DEBUG [cloud.vm.UserVmManagerImpl] (catalina-exec-14:null) THE WHERE CLAUSE IS: 2013-04-19 23:13:55,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:13:55,441 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:13:55,997 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2013-04-19 23:13:57,720 DEBUG [cloud.server.StatsCollector] (StatsCollector-1:null) HostStatsCollector is running... 2013-04-19 23:13:57,729 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-79:null) Seq 30-307298562: Executing request 2013-04-19 23:13:57,986 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-79:null) Seq 30-307298562: Response Received: 2013-04-19 23:13:57,987 DEBUG [agent.transport.Request] (StatsCollector-1:null) Seq 30-307298562: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetHostStatsAnswer } } 2013-04-19 23:14:05,396 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-4:null) Ping from 33 2013-04-19 23:14:06,189 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-16:null) submit async job-114, details: AsyncJobVO {id:114, userId: 2, accountId: 2, sessionKey: null, instanceType: VirtualMachine, instanceId: 4928, cmd: com.cloud.api.commands.StartVMCmd, cmdOriginator: null, cmdInfo: {"id":"8bad69e4-fe1c-47cc-befb-3ff18b804ed5","response":"json","sessionkey"= :"uSJrWetdj/um+FEIENmvZ7cVWh4\u003d","ctxUserId":"2","_":"1366406290251","c= txAccountId":"2","ctxStartEventId":"988"}, cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0, processStatus: 0, resultCode: 0, result: null, initMsid: 138942225534257, completeMsid: null, lastUpdated: null, lastPolled: null, created: null} 2013-04-19 23:14:06,191 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-5:job-114) Executing com.cloud.api.commands.StartVMCmd for job-114 2013-04-19 23:14:06,227 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:06,233 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:06,241 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: 30 new host id: null host id before state transition: null 2013-04-19 23:14:06,241 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Successfully transitioned to start state for VM[User|vm-web1] reservation id =3D bd80a54c-0444-4b93-9fd7-79adf66f5eca 2013-04-19 23:14:06,245 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Trying to deploy VM, vm has dcId: 3 and podId: 3 2013-04-19 23:14:06,246 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Deploy avoids pods: null, clusters: null, hosts: null 2013-04-19 23:14:06,249 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Root volume is ready, need to place VM in volume's cluster 2013-04-19 23:14:06,249 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Vol[4928|vm=3D4928|ROOT] is READY, changing deployment plan to use this pool's dcId: 3 , podId: 3 , and clusterId: 4 2013-04-19 23:14:06,250 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) DeploymentPlanner allocation algorithm: random 2013-04-19 23:14:06,250 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Trying to allocate a host and storage pools from dc:3, pod:3,cluster:4, requested cpu: 500, requested ram: 536870912 2013-04-19 23:14:06,250 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Is ROOT volume READY (pool already allocated)?: Ye= s 2013-04-19 23:14:06,250 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) This VM has last host_id specified, trying to choose the same host: 30 2013-04-19 23:14:06,254 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Checking if host: 30 has enough capacity for requested CPU: 500 and requested RAM: 536870912 , cpuOverprovisioningFactor: 1.0 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Hosts's actual total CPU: 42560 and CPU after applying overprovisioning: 42560 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) We need to allocate to the last host again, so checking if there is enough reserved capacity 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Reserved CPU: 1500 , Requested CPU: 500 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Reserved RAM: 1610612736 , Requested RAM: 53687091= 2 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Host has enough CPU and RAM available 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) STATS: Can alloc CPU from host: 30, used: 1500, reserved: 1500, actual total: 42560, total with overprovisioning: 42560; requested cpu:500,alloc_from_last_host?:true ,considerReservedCapacity?: true 2013-04-19 23:14:06,258 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) STATS: Can alloc MEM from host: 30, used: 1476395008, reserved: 1610612736, total: 32899922496; requested mem: 536870912,alloc_from_last_host?:true ,considerReservedCapacity?: true 2013-04-19 23:14:06,258 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) The last host of this VM is UP and has enough capacity 2013-04-19 23:14:06,258 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Now checking for suitable pools under zone: 3, pod: 3, cluster: 4 2013-04-19 23:14:06,260 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Checking suitable pools for volume (Id, Type): (4928,ROOT) 2013-04-19 23:14:06,260 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 211 2013-04-19 23:14:06,262 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Planner need not allocate a pool for this volume since its READY 2013-04-19 23:14:06,262 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Checking suitable pools for volume (Id, Type): (4929,DATADISK) 2013-04-19 23:14:06,262 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Volume is in READY state and has pool already allocated, checking if pool can be reused, poolId: 211 2013-04-19 23:14:06,263 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Planner need not allocate a pool for this volume since its READY 2013-04-19 23:14:06,263 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2013-04-19 23:14:06,263 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Checking if host: 30 can access any suitable storage pool for volume: ROOT 2013-04-19 23:14:06,265 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Host: 30 can access pool: 211 2013-04-19 23:14:06,265 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-5:job-114) Checking pool 211 for storage, totalSize: 150311272448, usedBytes: 125359357952, usedPct: 0.8339983815609565, disable threshold: 0.85 2013-04-19 23:14:06,271 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-5:job-114) Checking pool: 211 for volume allocation [Vol[4928|vm=3D4928|ROOT]], maxSize : 150311272448, totalAllocatedSize : 123639693312, askingSize : 0, allocated disable threshold: 0.85 2013-04-19 23:14:06,271 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Checking if host: 30 can access any suitable storage pool for volume: DATADISK 2013-04-19 23:14:06,273 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Host: 30 can access pool: 211 2013-04-19 23:14:06,273 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-5:job-114) Checking pool 211 for storage, totalSize: 150311272448, usedBytes: 125359357952, usedPct: 0.8339983815609565, disable threshold: 0.85 2013-04-19 23:14:06,279 DEBUG [cloud.storage.StorageManagerImpl] (Job-Executor-5:job-114) Checking pool: 211 for volume allocation [Vol[4928|vm=3D4928|ROOT], Vol[4929|vm=3D4928|DATADISK]], maxSize : 150311272448, totalAllocatedSize : 123639693312, askingSize : 0, allocated disable threshold: 0.85 2013-04-19 23:14:06,279 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Found a potential host id: 30 name: xenserver-yotavzei and associated storage pools for this VM 2013-04-19 23:14:06,280 DEBUG [cloud.deploy.FirstFitPlanner] (Job-Executor-5:job-114) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id= ))] : Dest[Zone(3)-Pod(3)-Cluster(4)-Host(30)-Storage()] 2013-04-19 23:14:06,280 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Deployment found - P0=3DVM[User|vm-web1], P0=3DDest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Po= ol(Id))] : Dest[Zone(3)-Pod(3)-Cluster(4)-Host(30)-Storage()] 2013-04-19 23:14:06,287 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: 30 new host id: 30 host id before state transition: null 2013-04-19 23:14:06,289 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) VM starting again on the last host it was stopped on 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Hosts's actual total CPU: 42560 and CPU after applying overprovisioning: 42560 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) We are allocating VM, increasing the used capacity of this host:30 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Current Used CPU: 1500 , Free CPU:39560 ,Requested CPU: 500 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Current Used RAM: 1476395008 , Free RAM:29812914752 ,Requested RAM: 536870912 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) We are allocating VM to the last host again, so adjusting the reserved capacity if it is not less than required 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Reserved CPU: 1500 , Requested CPU: 500 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Reserved RAM: 1610612736 , Requested RAM: 53687091= 2 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) CPU STATS after allocation: for host: 30, old used: 1500, old reserved: 1500, actual total: 42560, total with overprovisioning: 42560; new used:2000, reserved:1000; requested cpu:500,alloc_from_last:true 2013-04-19 23:14:06,296 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) RAM STATS after allocation: for host: 30, old used: 1476395008, old reserved: 1610612736, total: 32899922496; new used: 2013265920, reserved: 1073741824; requested mem: 536870912,alloc_from_last:true 2013-04-19 23:14:06,300 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) VM is being created in podId: 3 2013-04-19 23:14:06,304 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Lock is acquired for network id 214 as a part of network implement 2013-04-19 23:14:06,304 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking ExternalGuestNetworkGuru to implement Ntwk[214|Guest|12] 2013-04-19 23:14:06,334 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking VpcVirtualRouter to implemenet Ntwk[214|Guest|12] 2013-04-19 23:14:06,337 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Deploying Virtual Router in VPC [VPC [2-vpc_test1] 2013-04-19 23:14:06,351 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Adding vm VM[DomainRouter|r-4951-VM] to network Ntwk[214|Guest|12]; requested nic profile null 2013-04-19 23:14:06,364 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Allocating nic for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12] with requested profile null 2013-04-19 23:14:06,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:06,395 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Nic is allocated successfully for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12] 2013-04-19 23:14:06,409 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking VirtualRouter to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking Ovs to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking ExternalDhcpServer to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking BareMetal to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking SecurityGroupProvider to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,421 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking VpcVirtualRouter to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,423 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking NiciraNvp to prepare for Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:06,424 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:06,424 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Nic is prepared successfully for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12] 2013-04-19 23:14:06,433 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Plugging nic for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12] 2013-04-19 23:14:06,438 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298563: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic"= :false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1","net= mask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10","dns= 1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadc= astUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEnabled"= :false,"name":"ground1"},"instanceName":"r-4951-VM","wait":0}}] } 2013-04-19 23:14:06,438 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298563: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"PlugNicCommand":{"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic"= :false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1","net= mask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10","dns= 1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","broadc= astUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEnabled"= :false,"name":"ground1"},"instanceName":"r-4951-VM","wait":0}}] } 2013-04-19 23:14:06,439 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-139:null) Seq 30-307298563: Executing request 2013-04-19 23:14:06,583 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-139:null) Creating VIF for r-4951-VM on nic [Nic:Guest-172.28.2.1-vlan://2518] 2013-04-19 23:14:06,590 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-139:null) Looking for network named ground1 2013-04-19 23:14:06,627 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-139:null) Found a network called ground1 on host=3D172.20.0.13= ; Network=3D4e625494-53fe-bded-9dc1-2d728ba82f0c; pif=3D5acca3d7-b3af-7ac7-26f1-9f5f74bac285 2013-04-19 23:14:06,649 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-139:null) Found a network called VLAN-4e625494-53fe-bded-9dc1-2d728ba82f0c-2518 on host=3D172.20.0.13; Network=3D681e5722-f9a8-e638-c3a1-35b3d8f0c55a; pif=3D0e903d25-3afe-7cc5-432b-c21d2b3117c1 2013-04-19 23:14:06,674 DEBUG [xen.resource.CitrixResourceBase] (DirectAgent-139:null) Created a vif eee80f1f-6e86-3fd2-8f49-1f03a91266ae on 2 2013-04-19 23:14:07,163 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-139:null) Seq 30-307298563: Response Received: 2013-04-19 23:14:07,163 DEBUG [agent.transport.Request] (DirectAgent-139:null) Seq 30-307298563: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, [{"PlugNicAnswer":{"result":true,"details":"success","wait":0}}] } 2013-04-19 23:14:07,164 DEBUG [agent.manager.AgentAttache] (DirectAgent-139:null) Seq 30-307298563: No more commands found 2013-04-19 23:14:07,164 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298563: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, { PlugNicAnswer } } 2013-04-19 23:14:07,164 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Nic is plugged successfully for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12]. Vm is a part of network now 2013-04-19 23:14:07,183 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:07,198 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298564: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"172.28.2.1","networkDomain":"z03= .cloud.mydomain.tld","defaultDns1":"8.8.8.8","defaultDns2":"8.8.8.8","isRed= undant":false,"add":true,"nic":{"deviceId":2,"networkRateMbps":1000,"defaul= tNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1"= ,"netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10"= ,"dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","b= roadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEna= bled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.= 1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.brid= ge":"172.28.2.255"," router.name":"r-4951-VM","router.ip":"169.254.3.239"},"wait":0}}] } 2013-04-19 23:14:07,199 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298564: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"172.28.2.1","networkDomain":"z03= .cloud.mydomain.tld","defaultDns1":"8.8.8.8","defaultDns2":"8.8.8.8","isRed= undant":false,"add":true,"nic":{"deviceId":2,"networkRateMbps":1000,"defaul= tNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1"= ,"netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10"= ,"dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","b= roadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEna= bled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.= 1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.brid= ge":"172.28.2.255"," router.name":"r-4951-VM","router.ip":"169.254.3.239"},"wait":0}}] } 2013-04-19 23:14:07,199 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:null) Seq 30-307298564: Executing request 2013-04-19 23:14:07,643 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running... 2013-04-19 23:14:07,703 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 33-600178739: Received: { Ans: , MgmtId: 138942225534257, via: 33, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:14:07,710 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-19:null) Seq 30-307298565: Executing request 2013-04-19 23:14:14,473 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-140:null) Seq 30-307298564: Response Received: 2013-04-19 23:14:14,474 DEBUG [agent.transport.Request] (DirectAgent-140:null) Seq 30-307298564: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] = } 2013-04-19 23:14:14,474 DEBUG [agent.manager.AgentAttache] (DirectAgent-140:null) Seq 30-307298564: No more commands found 2013-04-19 23:14:14,474 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298564: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } = } 2013-04-19 23:14:14,474 DEBUG [network.router.VpcVirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Succesfully added router VM[DomainRouter|r-4951-VM] to guest network Ntwk[214|Guest|12] 2013-04-19 23:14:14,474 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-5:job-114) Successfully added VPC router VM[DomainRouter|r-4951-VM] to guest network Ntwk[214|Guest|12] 2013-04-19 23:14:14,474 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Reprogramming network Ntwk[214|Guest|12] as a part of network implement 2013-04-19 23:14:14,493 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:14,524 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298566: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.157","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.155","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:14,525 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298566: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.157","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.155","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:14,525 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-242:null) Seq 30-307298566: Executing request 2013-04-19 23:14:15,892 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-242:null) Seq 30-307298566: Response Received: 2013-04-19 23:14:15,892 DEBUG [agent.transport.Request] (DirectAgent-242:null) Seq 30-307298566: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.157 - success","10.14.5.155 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:15,892 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298566: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:15,897 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Cleaning up because we're unable to implement the network Ntwk[214|Guest|12] 2013-04-19 23:14:15,906 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Releasing 0 port forwarding rules for network id=3D214 as a part of shutdownNetworkRules 2013-04-19 23:14:15,907 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) There are no rules to forward to the network elements 2013-04-19 23:14:15,908 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Releasing 0 static nat rules for network id=3D214 = as a part of shutdownNetworkRules 2013-04-19 23:14:15,908 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) There are no rules to forward to the network elements 2013-04-19 23:14:15,909 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) There are no rules to forward to the network elements 2013-04-19 23:14:15,910 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Releasing 0 firewall rules for network id=3D214 as= a part of shutdownNetworkRules 2013-04-19 23:14:15,910 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) There are no rules to forward to the network elements 2013-04-19 23:14:15,915 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Releasing 8 Network ACLs for network id=3D214 as a part of shutdownNetworkRules 2013-04-19 23:14:15,936 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:15,968 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298567: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:15,969 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298567: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:15,969 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-9:null) Seq 30-307298567: Executing request 2013-04-19 23:14:17,343 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-9:null) Seq 30-307298567: Response Received: 2013-04-19 23:14:17,344 DEBUG [agent.transport.Request] (DirectAgent-9:null) Seq 30-307298567: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.155 - success","10.14.5.157 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:17,344 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298567: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:17,357 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying network acls in network Ntwk[214|Guest|12= ] 2013-04-19 23:14:17,379 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:17,396 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298568: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.SetNetworkACLCommand":{"rules":[{"id":0,"vlanTag":"2518","protoc= ol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList= ":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"icmp","rev= oked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"icmpType":-1,"icmpCode":-1,"trafficType":"Ingress"},{"id":0,"vlanTag":"= 2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":fa= lse,"cidrList":[" 172.28.1.0/24 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 172.28.1.0/24 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Egress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portR= ange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/32 "],"trafficType":"Egress"}],"nic":{"deviceId":2,"networkRateMbps":1000,"def= aultNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2= .1","netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:= 10","dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest"= ,"broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroup= Enabled":false,"name":"ground1"},"accessDetails":{"zone.network.type":"Adva= nced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"172= .28.2.1","guest.vlan.tag":"2518"},"wait":0}}] } 2013-04-19 23:14:17,398 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298568: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.SetNetworkACLCommand":{"rules":[{"id":0,"vlanTag":"2518","protoc= ol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList= ":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"icmp","rev= oked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"icmpType":-1,"icmpCode":-1,"trafficType":"Ingress"},{"id":0,"vlanTag":"= 2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":fa= lse,"cidrList":[" 172.28.1.0/24 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 172.28.1.0/24 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","port= Range":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/0 "],"trafficType":"Egress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portR= ange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":[" 0.0.0.0/32 "],"trafficType":"Egress"}],"nic":{"deviceId":2,"networkRateMbps":1000,"def= aultNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2= .1","netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:= 10","dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest"= ,"broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroup= Enabled":false,"name":"ground1"},"accessDetails":{"zone.network.type":"Adva= nced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"172= .28.2.1","guest.vlan.tag":"2518"},"wait":0}}] } 2013-04-19 23:14:17,398 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 30-307298568: Executing request 2013-04-19 23:14:18,817 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-244:null) Seq 30-307298568: Response Received: 2013-04-19 23:14:18,818 DEBUG [agent.transport.Request] (DirectAgent-244:null) Seq 30-307298568: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.SetNetworkACLAnswer":{"results":[null,null,null,null,null,null,n= ull,null],"result":true,"wait":0}}] } 2013-04-19 23:14:18,818 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298568: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { SetNetworkACLAnswer } } 2013-04-19 23:14:18,818 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Network Rules for network 214 were handled by VpcVirtualRouter 2013-04-19 23:14:18,836 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:18,867 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298569: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:18,868 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298569: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:18,868 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-48:null) Seq 30-307298569: Executing request 2013-04-19 23:14:19,387 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-19:null) Seq 30-307298565: Response Received: 2013-04-19 23:14:19,388 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 30-307298565: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:14:19,394 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-141:null) Seq 30-307298570: Executing request 2013-04-19 23:14:20,241 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-48:null) Seq 30-307298569: Response Received: 2013-04-19 23:14:20,242 DEBUG [agent.transport.Request] (DirectAgent-48:null) Seq 30-307298569: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.155 - success","10.14.5.157 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:20,242 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298569: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:20,256 DEBUG [network.rules.RulesManagerImpl] (Job-Executor-5:job-114) Found 2 static nats to disable for network id 214 2013-04-19 23:14:20,277 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:20,309 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298571: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:20,309 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298571: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":true,"oneToOneNat":true,"firstIP":false,= "vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifM= acAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","n= etworkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat":= false,"add":true,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlanGa= teway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:00= :02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"}]= ,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:20,310 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-245:null) Seq 30-307298571: Executing request 2013-04-19 23:14:21,553 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-2:null) Ping from 34 2013-04-19 23:14:21,696 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-245:null) Seq 30-307298571: Response Received: 2013-04-19 23:14:21,696 DEBUG [agent.transport.Request] (DirectAgent-245:null) Seq 30-307298571: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.155 - success","10.14.5.157 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:21,696 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298571: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:21,705 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying static nat rules in network Ntwk[214|Guest|12] 2013-04-19 23:14:21,719 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298572: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.SetStaticNatRulesCommand":{"rules":[{"dstIp":"172.28.2.18","id":= 0,"srcIp":"10.14.5.155","revoked":true,"alreadyAdded":false,"purpose":"Stat= icNat","icmpType":0,"icmpCode":0},{"dstIp":"172.28.2.208","id":0,"srcIp":"1= 0.14.5.157","revoked":true,"alreadyAdded":false,"purpose":"StaticNat","icmp= Type":0,"icmpCode":0}],"vpcId":2,"accessDetails":{"zone.network.type":"Adva= nced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"172= .28.2.1"},"wait":0}}] } 2013-04-19 23:14:21,719 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298572: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.SetStaticNatRulesCommand":{"rules":[{"dstIp":"172.28.2.18","id":= 0,"srcIp":"10.14.5.155","revoked":true,"alreadyAdded":false,"purpose":"Stat= icNat","icmpType":0,"icmpCode":0},{"dstIp":"172.28.2.208","id":0,"srcIp":"1= 0.14.5.157","revoked":true,"alreadyAdded":false,"purpose":"StaticNat","icmp= Type":0,"icmpCode":0}],"vpcId":2,"accessDetails":{"zone.network.type":"Adva= nced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"172= .28.2.1"},"wait":0}}] } 2013-04-19 23:14:21,720 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-246:null) Seq 30-307298572: Executing request 2013-04-19 23:14:22,784 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-246:null) Seq 30-307298572: Response Received: 2013-04-19 23:14:22,785 DEBUG [agent.transport.Request] (DirectAgent-246:null) Seq 30-307298572: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.SetStaticNatRulesAnswer":{"results":[null,null],"result":true,"w= ait":0}}] } 2013-04-19 23:14:22,785 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298572: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { SetStaticNatRulesAnswer } } 2013-04-19 23:14:22,785 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Static Nat for network 214 were handled by VpcVirtualRouter 2013-04-19 23:14:22,806 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:22,837 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298573: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":false,"oneToOneNat":true,"firstIP":false= ,"vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vif= MacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","= networkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat"= :false,"add":false,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlan= Gateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:= 00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"= }],"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:22,838 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298573: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":false,"oneToOneNat":true,"firstIP":false= ,"vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vif= MacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","= networkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat"= :false,"add":false,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlan= Gateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:= 00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"= }],"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:22,838 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-20:null) Seq 30-307298573: Executing request 2013-04-19 23:14:23,897 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-20:null) Seq 30-307298573: Response Received: 2013-04-19 23:14:23,898 DEBUG [agent.transport.Request] (DirectAgent-20:null) Seq 30-307298573: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.155 - success","10.14.5.157 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:23,899 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298573: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:23,919 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (Job-Executor-5:job-114) Applying vpc ip association in network Ntwk[214|Guest|12] 2013-04-19 23:14:23,949 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298574: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":false,"oneToOneNat":true,"firstIP":false= ,"vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vif= MacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","= networkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat"= :false,"add":false,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlan= Gateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:= 00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"= }],"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:23,950 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298574: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100001, [{"routing.IpAssocVpcCommand":{"ipAddresses":[{"accountId":2,"publicIp":"10= .14.5.155","sourceNat":false,"add":false,"oneToOneNat":true,"firstIP":false= ,"vlanId":"2020","vlanGateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vif= MacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","= networkName":"ground1"},{"accountId":2,"publicIp":"10.14.5.157","sourceNat"= :false,"add":false,"oneToOneNat":true,"firstIP":false,"vlanId":"2020","vlan= Gateway":"10.14.0.1","vlanNetmask":"255.254.0.0","vifMacAddress":"06:51:10:= 00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"= }],"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-4951-VM","router.ip":"169.254.3.239","router.guest.ip":"10.= 14.4.148"},"wait":0}}] } 2013-04-19 23:14:23,951 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-145:null) Seq 30-307298574: Executing request 2013-04-19 23:14:24,968 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-145:null) Seq 30-307298574: Response Received: 2013-04-19 23:14:24,969 DEBUG [agent.transport.Request] (DirectAgent-145:null) Seq 30-307298574: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, [{"routing.IpAssocAnswer":{"results":["10.14.5.155 - success","10.14.5.157 - success"],"result":true,"wait":0}}] } 2013-04-19 23:14:24,969 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298574: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 0, { IpAssocAnswer } } 2013-04-19 23:14:24,974 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Sending network shutdown to VpcVirtualRouter 2013-04-19 23:14:24,992 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:25,012 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:25,025 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298575: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"172.28.2.1","networkDomain":"z03= .cloud.mydomain.tld","defaultDns1":"8.8.8.8","defaultDns2":"8.8.8.8","isRed= undant":false,"add":false,"nic":{"deviceId":2,"networkRateMbps":1000,"defau= ltNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1= ","netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10= ","dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","= broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEn= abled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2= .1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bri= dge":"172.28.2.255"," router.name":"r-4951-VM","router.ip":"169.254.3.239"},"wait":0}}] } 2013-04-19 23:14:25,026 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298575: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"SetupGuestNetworkCommand":{"dhcpRange":"172.28.2.1","networkDomain":"z03= .cloud.mydomain.tld","defaultDns1":"8.8.8.8","defaultDns2":"8.8.8.8","isRed= undant":false,"add":false,"nic":{"deviceId":2,"networkRateMbps":1000,"defau= ltNic":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1= ","netmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10= ","dns1":"8.8.8.8","dns2":"8.8.8.8","broadcastType":"Vlan","type":"Guest","= broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEn= abled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2= .1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bri= dge":"172.28.2.255"," router.name":"r-4951-VM","router.ip":"169.254.3.239"},"wait":0}}] } 2013-04-19 23:14:25,027 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-81:null) Seq 30-307298575: Executing request 2013-04-19 23:14:25,291 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 3 is ready to launch secondary storage VM 2013-04-19 23:14:25,445 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 3 is ready to launch console proxy 2013-04-19 23:14:25,998 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 1 routers. 2013-04-19 23:14:30,480 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-81:null) Seq 30-307298575: Response Received: 2013-04-19 23:14:30,481 DEBUG [agent.transport.Request] (DirectAgent-81:null) Seq 30-307298575: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, [{"SetupGuestNetworkAnswer":{"result":true,"details":"success","wait":0}}] = } 2013-04-19 23:14:30,481 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298575: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, { SetupGuestNetworkAnswer } = } 2013-04-19 23:14:30,481 DEBUG [agent.manager.AgentAttache] (DirectAgent-81:null) Seq 30-307298575: No more commands found 2013-04-19 23:14:30,506 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:30,510 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Un-plugging nic for vm VM[DomainRouter|r-4951-VM] from network Ntwk[214|Guest|12] 2013-04-19 23:14:30,514 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298576: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNi= c":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1","n= etmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10","b= roadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2518","isolation= Uri":"vlan://2518","isSecurityGroupEnabled":false,"name":"ground1"},"instan= ceName":"r-4951-VM","wait":0}}] } 2013-04-19 23:14:30,514 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298576: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"UnPlugNicCommand":{"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNi= c":false,"uuid":"badb483a-88d8-4667-ab4d-638e8e40b9ec","ip":"172.28.2.1","n= etmask":"255.255.255.0","gateway":"172.28.2.1","mac":"02:00:77:06:00:10","b= roadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2518","isolation= Uri":"vlan://2518","isSecurityGroupEnabled":false,"name":"ground1"},"instan= ceName":"r-4951-VM","wait":0}}] } 2013-04-19 23:14:30,515 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-30:null) Seq 30-307298576: Executing request 2013-04-19 23:14:31,205 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-141:null) Seq 30-307298570: Response Received: 2013-04-19 23:14:31,206 DEBUG [agent.transport.Request] (StatsCollector-3:null) Seq 30-307298570: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2013-04-19 23:14:31,371 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-30:null) Seq 30-307298576: Response Received: 2013-04-19 23:14:31,372 DEBUG [agent.transport.Request] (DirectAgent-30:null) Seq 30-307298576: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, [{"UnPlugNicAnswer":{"result":true,"details":"success","wait":0}}] } 2013-04-19 23:14:31,372 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298576: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, { UnPlugNicAnswer } } 2013-04-19 23:14:31,372 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Nic is unplugged successfully for vm VM[DomainRouter|r-4951-VM] in network Ntwk[214|Guest|12] 2013-04-19 23:14:31,373 DEBUG [agent.manager.AgentAttache] (DirectAgent-30:null) Seq 30-307298576: No more commands found 2013-04-19 23:14:31,380 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking VirtualRouter to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking Ovs to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking ExternalDhcpServer to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking BareMetal to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking SecurityGroupProvider to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking VpcVirtualRouter to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Asking NiciraNvp to release Nic[19750-4951-null-172.28.2.1] 2013-04-19 23:14:31,392 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Successfully released nic Nic[19750-4951-null-172.28.2.1]for vm VM[DomainRouter|r-4951-VM] 2013-04-19 23:14:31,399 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Service SecurityGroup is not supported in the network id=3D214 2013-04-19 23:14:31,409 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Removed nic id=3D19750 2013-04-19 23:14:31,413 DEBUG [network.element.VpcVirtualRouterElement] (Job-Executor-5:job-114) Successfully unplugged nic in network Ntwk[214|Guest|12] for virtual router VM[DomainRouter|r-4951-VM] 2013-04-19 23:14:31,413 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Network id=3D214 is shutdown successfully, cleanin= g up corresponding resources now. 2013-04-19 23:14:31,415 DEBUG [network.guru.GuestNetworkGuru] (Job-Executor-5:job-114) Releasing vnet for the network id=3D214 2013-04-19 23:14:31,425 DEBUG [cloud.network.NetworkManagerImpl] (Job-Executor-5:job-114) Lock is released for network id 214 as a part of network implement 2013-04-19 23:14:31,425 ERROR [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Failed to start instance VM[User|vm-web1] java.lang.NullPointerException at com.cloud.network.NetworkManagerImpl.getIpInNetwork(NetworkManagerImpl.java= :4134) at com.cloud.network.rules.RulesManagerImpl.applyStaticNatsForNetwork(RulesMan= agerImpl.java:887) at com.cloud.network.NetworkManagerImpl.reprogramNetworkRules(NetworkManagerIm= pl.java:3909) at com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(N= etworkManagerImpl.java:2043) at com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.ja= va:1965) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.network.NetworkManagerImpl.prepare(NetworkManagerImpl.java:2110) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerIm= pl.java:752) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java= :472) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2= 929) at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1= 842) at com.cloud.event.ActionEventCallback.intercept(ActionEventCallback.java:36) at com.cloud.api.commands.StartVMCmd.execute(StartVMCmd.java:123) at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:138) at com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:432) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1= 145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:= 615) at java.lang.Thread.run(Thread.java:722) 2013-04-19 23:14:31,429 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Cleaning up resources for the vm VM[User|vm-web1] in Starting state 2013-04-19 23:14:31,431 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298577: Sending { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-4928-VM","wait":0}}] } 2013-04-19 23:14:31,431 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298577: Executing: { Cmd , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 100111, [{"StopCommand":{"isProxy":false,"vmName":"i-2-4928-VM","wait":0}}] } 2013-04-19 23:14:31,431 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-146:null) Seq 30-307298577: Executing request 2013-04-19 23:14:31,535 INFO [xen.resource.CitrixResourceBase] (DirectAgent-146:null) VM does not exist on XenServer18c3d5b0-1005-40ea-a1e5-3d59b1beaf3b 2013-04-19 23:14:31,535 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-146:null) Seq 30-307298577: Response Received: 2013-04-19 23:14:31,536 DEBUG [agent.transport.Request] (DirectAgent-146:null) Seq 30-307298577: Processing: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, [{"StopAnswer":{"vncPort":0,"result":true,"details":"VM does not exist","wait":0}}] } 2013-04-19 23:14:31,536 DEBUG [agent.manager.AgentAttache] (DirectAgent-146:null) Seq 30-307298577: No more commands found 2013-04-19 23:14:31,536 DEBUG [agent.transport.Request] (Job-Executor-5:job-114) Seq 30-307298577: Received: { Ans: , MgmtId: 138942225534257, via: 30, Ver: v1, Flags: 110, { StopAnswer } } 2013-04-19 23:14:31,542 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Successfully released network resources for the vm VM[User|vm-web1] 2013-04-19 23:14:31,542 DEBUG [cloud.vm.VirtualMachineManagerImpl] (Job-Executor-5:job-114) Successfully cleanued up resources for the vm VM[User|vm-web1] in Starting state 2013-04-19 23:14:31,549 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: 30 new host id: null host id before state transition: 30 2013-04-19 23:14:31,555 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) Hosts's actual total CPU: 42560 and CPU after applying overprovisioning: 42560 2013-04-19 23:14:31,555 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) release cpu from host: 30, old used: 2000,reserved: 1000, actual total: 42560, total with overprovisioning: 42560; new used: 1500,reserved:1000; movedfromreserved: false,moveToReserveredfalse 2013-04-19 23:14:31,555 DEBUG [cloud.capacity.CapacityManagerImpl] (Job-Executor-5:job-114) release mem from host: 30, old used: 2013265920,reserved: 1073741824, total: 32899922496; new used: 1476395008,reserved:1073741824; movedfromreserved: false,moveToReserveredfalse 2013-04-19 23:14:31,563 DEBUG [cloud.async.AsyncJobManagerImpl] (Job-Executor-5:job-114) Complete async job-114, jobStatus: 2, resultCode: 530, result: Error Code: 534 Error text: Resource [Host:30] is unreachable: Host 30: Unable to start instance due to null 2013-04-19 23:14:31,596 DEBUG [cloud.async.AsyncJobManagerImpl] (catalina-exec-21:null) Async job-114 completed 2013-04-19 23:14:33,075 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-137:null) Ping from 30 2013-04-19 23:14:40,021 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) VmStatsCollector is running... --047d7b33d2143e4bfd04dabd8d69--