You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cloudstack.apache.org by benoit lair <ku...@gmail.com> on 2013/04/19 23:39:20 UTC
CS 4.0.0 - Bug onto xcp server 1.1 - can't launch any vm

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=1
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","ctxAccountId":"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=214
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=214
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 = 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=4928|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)?: Yes
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: 536870912
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=4928|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=4928|ROOT], Vol[4929|vm=4928|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=VM[User|vm-web1],
P0=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,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: 536870912
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=214
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=214
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=214
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","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","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","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","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=172.20.0.13;
Network=4e625494-53fe-bded-9dc1-2d728ba82f0c;
pif=5acca3d7-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=172.20.0.13;
Network=681e5722-f9a8-e638-c3a1-35b3d8f0c55a;
pif=0e903d25-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=214
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","isRedundant":false,"add":true,"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bridge":"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","isRedundant":false,"add":true,"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bridge":"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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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=214 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=214 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=214 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=214 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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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=214
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","protocol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"icmp","revoked":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":false,"cidrList":["
172.28.1.0/24
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
172.28.1.0/24
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Egress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/32
"],"trafficType":"Egress"}],"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"zone.network.type":"Advanced","
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","protocol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"icmp","revoked":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":false,"cidrList":["
172.28.1.0/24
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
172.28.1.0/24
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Ingress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[80,80],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/0
"],"trafficType":"Egress"},{"id":0,"vlanTag":"2518","protocol":"tcp","portRange":[22,22],"revoked":true,"alreadyAdded":false,"cidrList":["
0.0.0.0/32
"],"trafficType":"Egress"}],"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"zone.network.type":"Advanced","
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,null,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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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","vifMacAddress":"06:51:10:00:02:92","networkRate":1000,"trafficType":"Public","networkName":"ground1"},{"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","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":"StaticNat","icmpType":0,"icmpCode":0},{"dstIp":"172.28.2.208","id":0,"srcIp":"10.14.5.157","revoked":true,"alreadyAdded":false,"purpose":"StaticNat","icmpType":0,"icmpCode":0}],"vpcId":2,"accessDetails":{"zone.network.type":"Advanced","
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":"StaticNat","icmpType":0,"icmpCode":0},{"dstIp":"172.28.2.208","id":0,"srcIp":"10.14.5.157","revoked":true,"alreadyAdded":false,"purpose":"StaticNat","icmpType":0,"icmpCode":0}],"vpcId":2,"accessDetails":{"zone.network.type":"Advanced","
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,"wait":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","vifMacAddress":"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","vlanGateway":"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","vifMacAddress":"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","vlanGateway":"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","vifMacAddress":"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","vlanGateway":"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","vifMacAddress":"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","vlanGateway":"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=214
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=214
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","isRedundant":false,"add":false,"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bridge":"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","isRedundant":false,"add":false,"nic":{"deviceId":2,"networkRateMbps":1000,"defaultNic":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","isSecurityGroupEnabled":false,"name":"ground1"},"accessDetails":{"router.guest.ip":"172.28.2.1","guest.vlan.tag":"2518","guest.network.gateway":"172.28.2.1","guest.bridge":"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=214
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,"defaultNic":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","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEnabled":false,"name":"ground1"},"instanceName":"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,"defaultNic":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","broadcastType":"Vlan","type":"Guest","broadcastUri":"vlan://2518","isolationUri":"vlan://2518","isSecurityGroupEnabled":false,"name":"ground1"},"instanceName":"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=214
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=214
2013-04-19 23:14:31,409 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-5:job-114) Removed nic id=19750
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=214 is shutdown successfully, cleaning
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=214
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(RulesManagerImpl.java:887)
at
com.cloud.network.NetworkManagerImpl.reprogramNetworkRules(NetworkManagerImpl.java:3909)
at
com.cloud.network.NetworkManagerImpl.implementNetworkElementsAndResources(NetworkManagerImpl.java:2043)
at
com.cloud.network.NetworkManagerImpl.implementNetwork(NetworkManagerImpl.java: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(VirtualMachineManagerImpl.java:752)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:2929)
at
com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:1842)
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:1145)
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...